Comments (11)
icefoxen
commented on June 14, 2024
This is actually a little more complicated; receive_message() is called here: https://github.com/icefoxen/WorldDat/blob/master/src/peer.rs#L266
and causes the panic as described, but before I did some refactoring it was called here: https://github.com/icefoxen/WorldDat/blob/02704765beded20785f3db8e632d9909ede213bb/src/peer.rs#L394
and did not panic. I don't THINK I'm doing anything differently between the cases...
from quinn.
Ralith
commented on June 14, 2024
Currently blocked on getting a backtrace to the remove_entry call in connection.rs (the one location where streams are forgotten) in master, if the issue indeed repros in master.
from quinn.
icefoxen
commented on June 14, 2024
It now doesn't crash but also doesn't seem to establish outgoing connections...
from quinn.
Ralith
commented on June 14, 2024
In lieu of a repro, trace-level logs from both sides of the failed connection attempt would be helpful.
from quinn.
icefoxen
commented on June 14, 2024
Ugh. I get basically nothing from the listener, but the port is open and it used to work before I changed things, so I assume I'm doing something wrong.
From the outgoing connection, I get this:
Oct 28 22:25:58.706 TRCE outgoing
Oct 28 22:25:58.706 TRCE initial dcid, value: a2b05ad0e6a50ff5e04b039645ff100252b7
Oct 28 22:25:58.709 TRCE sending handshake packet, pn: 2156971447
Oct 28 22:25:58.709 TRCE STREAM, fin: false, len: 240, off: 0, id: 0
Oct 28 22:25:58.709 TRCE timer start, time: 10.003038s, timer: Idle
Oct 28 22:25:58.709 TRCE timer start, time: 203.038ms, timer: LossDetection
Oct 28 22:25:58.910 TRCE timeout, timer: LossDetection
Oct 28 22:25:58.911 TRCE retransmitting handshake packets, connection: 1a9ff788e86320ee
Oct 28 22:25:58.911 TRCE sending handshake packet, pn: 2156971448
Oct 28 22:25:58.911 TRCE STREAM, fin: false, len: 240, off: 0, id: 0
Oct 28 22:25:58.912 TRCE timer start, time: 10.204348s, timer: Idle
Oct 28 22:25:58.912 TRCE timer start, time: 604.348ms, timer: LossDetection
Oct 28 22:25:59.312 TRCE timeout, timer: LossDetection
Oct 28 22:25:59.313 TRCE retransmitting handshake packets, connection: 1a9ff788e86320ee
Oct 28 22:25:59.313 TRCE sending handshake packet, pn: 2156971449
Oct 28 22:25:59.313 TRCE STREAM, fin: false, len: 240, off: 0, id: 0
Oct 28 22:25:59.314 TRCE timer start, time: 10.606368s, timer: Idle
Oct 28 22:25:59.314 TRCE timer start, time: 1.406368s, timer: LossDetection
Oct 28 22:26:00.114 TRCE timeout, timer: LossDetection
Oct 28 22:26:00.115 TRCE retransmitting handshake packets, connection: 1a9ff788e86320ee
Oct 28 22:26:00.115 TRCE sending handshake packet, pn: 2156971450
Oct 28 22:26:00.115 TRCE STREAM, fin: false, len: 240, off: 0, id: 0
Oct 28 22:26:00.116 TRCE timer start, time: 11.408362s, timer: Idle
Oct 28 22:26:00.116 TRCE timer start, time: 3.008362s, timer: LossDetection
Oct 28 22:26:01.716 TRCE timeout, timer: LossDetection
Oct 28 22:26:01.716 TRCE retransmitting handshake packets, connection: 1a9ff788e86320ee
Oct 28 22:26:01.716 TRCE sending handshake packet, pn: 2156971451
Oct 28 22:26:01.716 TRCE STREAM, fin: false, len: 240, off: 0, id: 0
Oct 28 22:26:01.717 TRCE timer start, time: 13.009516s, timer: Idle
Oct 28 22:26:01.717 TRCE timer start, time: 6.209516s, timer: LossDetection
Oct 28 22:26:04.917 TRCE timeout, timer: LossDetection
Oct 28 22:26:04.917 TRCE retransmitting handshake packets, connection: 1a9ff788e86320ee
Oct 28 22:26:04.918 TRCE sending handshake packet, pn: 2156971452
Oct 28 22:26:04.918 TRCE STREAM, fin: false, len: 240, off: 0, id: 0
Oct 28 22:26:04.918 TRCE timer start, time: 16.210896s, timer: Idle
Oct 28 22:26:04.918 TRCE timer start, time: 12.610896s, timer: LossDetection
Oct 28 22:26:11.318 TRCE timeout, timer: LossDetection
Oct 28 22:26:11.318 TRCE retransmitting handshake packets, connection: 1a9ff788e86320ee
Oct 28 22:26:11.318 TRCE sending handshake packet, pn: 2156971453
Oct 28 22:26:11.319 TRCE STREAM, fin: false, len: 240, off: 0, id: 0
Oct 28 22:26:11.319 TRCE timer start, time: 22.611649s, timer: Idle
Oct 28 22:26:11.319 TRCE timer start, time: 25.411649s, timer: LossDetection
Oct 28 22:26:21.319 TRCE timeout, timer: Idle
Oct 28 22:26:21.319 TRCE connection closed
Oct 28 22:26:21.320 TRCE timer stop, timer: LossDetection
from quinn.
Ralith
commented on June 14, 2024
Thanks for the info! That looks like a standard clientside timeout due to no response ever being received from the server. Reviewing the state machine, I don't immediately see any way for the server to process an initial packet without logging something at trace or debug level. Can you double-check that trace logging is working on the server (e.g. by inserting an unconditional trace message after everything's set up) and that the server's UDP socket is open and listening (e.g. with ss -lupn)?
from quinn.
icefoxen
commented on June 14, 2024
Results of this morning's flailing around:
Added an slog trace call right before calling runtime.block_on(driver), it outputs okay.
I confirmed with gdb and strace that it is blocking on epoll_wait(), when I send garbage data to the UDP port with netcat it breaks out of the epoll_wait() and then returns to it.
Used gdb to break on Driver::poll as you suggested in IRC, and then stepping through, it goes through the following code:
at .../quinn/src/lib.rs:641
641 let mut buf = [0; 64 * 1024];
642 let endpoint = &mut *self.0.borrow_mut();
643 if endpoint.driver.is_none() {
644 endpoint.driver = Some(task::current());
643 if endpoint.driver.is_none() {
646 let now = micros_from(endpoint.epoch.elapsed());
649 match endpoint.socket.poll_recv_from(&mut buf) {
650 Ok(Async::Ready((n, addr))) => {
666 }
656 break;
667 while let Some((connection, event)) = endpoint.inner.poll() {
756 let mut blocked = false;
757 while !endpoint.outgoing.is_empty() {
777 while let Some(io) = endpoint.inner.poll_io(now) {
865 while let Ok(Async::Ready(_)) = endpoint.incoming.poll_ready() {
866 if let Some(x) = endpoint.inner.accept() {
872 break;
878 let _ = endpoint.incoming.poll_complete();
879 let mut fired = false;
881 match endpoint.timers.poll() {
882 Ok(Async::Ready(Some(Some((conn, timer))))) => {
894 if !fired {
898 Ok(Async::NotReady)Then it descends into tokio and eventually blocks on self.executor.park.park() in tokio-current-thread-0.1.3/src/lib.rs:490. Then when I send junk data to the port again it unblocks and does this:
641 let mut buf = [0; 64 * 1024];
642 let endpoint = &mut *self.0.borrow_mut();
643 if endpoint.driver.is_none() {
646 let now = micros_from(endpoint.epoch.elapsed());
649 match endpoint.socket.poll_recv_from(&mut buf) {
650 Ok(Async::Ready((n, addr))) => {
651 endpoint
653 .handle(now, normalize(addr), (&buf[0..n]).into());
651 endpoint
666 }
648 loop {
649 match endpoint.socket.poll_recv_from(&mut buf) {
650 Ok(Async::Ready((n, addr))) => {
666 }
656 break;
667 while let Some((connection, event)) = endpoint.inner.poll() {
756 let mut blocked = false;
757 while !endpoint.outgoing.is_empty() {
777 while let Some(io) = endpoint.inner.poll_io(now) {
865 while let Ok(Async::Ready(_)) = endpoint.incoming.poll_ready() {
866 if let Some(x) = endpoint.inner.accept() {
872 break;
878 let _ = endpoint.incoming.poll_complete();
879 let mut fired = false;
881 match endpoint.timers.poll() {
882 Ok(Async::Ready(Some(Some((conn, timer))))) => {
894 if !fired {
898 Ok(Async::NotReady)Then when I send it a connection request using the client code, it goes through this, then blocks on executor.park.park() again:
641 let mut buf = [0; 64 * 1024];
642 let endpoint = &mut *self.0.borrow_mut();
643 if endpoint.driver.is_none() {
646 let now = micros_from(endpoint.epoch.elapsed());
649 match endpoint.socket.poll_recv_from(&mut buf) {
650 Ok(Async::Ready((n, addr))) => {
651 endpoint
653 .handle(now, normalize(addr), (&buf[0..n]).into());
651 endpoint
666 }
648 loop {
649 match endpoint.socket.poll_recv_from(&mut buf) {
650 Ok(Async::Ready((n, addr))) => {
651 endpoint
653 .handle(now, normalize(addr), (&buf[0..n]).into());
651 endpoint
666 }
648 loop {
649 match endpoint.socket.poll_recv_from(&mut buf) {
650 Ok(Async::Ready((n, addr))) => {
651 endpoint
653 .handle(now, normalize(addr), (&buf[0..n]).into());
651 endpoint
666 }
648 loop {
649 match endpoint.socket.poll_recv_from(&mut buf) {
650 Ok(Async::Ready((n, addr))) => {
651 endpoint
653 .handle(now, normalize(addr), (&buf[0..n]).into());
651 endpoint
666 }
648 loop {
649 match endpoint.socket.poll_recv_from(&mut buf) {
650 Ok(Async::Ready((n, addr))) => {
651 endpoint
653 .handle(now, normalize(addr), (&buf[0..n]).into());
651 endpoint
666 }
648 loop {
649 match endpoint.socket.poll_recv_from(&mut buf) {
650 Ok(Async::Ready((n, addr))) => {
651 endpoint
653 .handle(now, normalize(addr), (&buf[0..n]).into());
651 endpoint
666 }
648 loop {
649 match endpoint.socket.poll_recv_from(&mut buf) {
650 Ok(Async::Ready((n, addr))) => {
666 }
656 break;
667 while let Some((connection, event)) = endpoint.inner.poll() {
756 let mut blocked = false;
757 while !endpoint.outgoing.is_empty() {
777 while let Some(io) = endpoint.inner.poll_io(now) {
865 while let Ok(Async::Ready(_)) = endpoint.incoming.poll_ready() {
866 if let Some(x) = endpoint.inner.accept() {
872 break;
878 let _ = endpoint.incoming.poll_complete();
879 let mut fired = false;
881 match endpoint.timers.poll() {
882 Ok(Async::Ready(Some(Some((conn, timer))))) => {
894 if !fired {
898 Ok(Async::NotReady)
899 }
...tokio junk, just returning from functions...
<tokio_current_thread::Entered<'a, P>>::block_on (self=0x7fffffffc4b8, future=...)
at /home/icefox/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-current-thread-0.1.3/src/lib.rs:480
480 });
482 match res {
483 Ok(Async::Ready(e)) => return Ok(e),
488 self.tick();
490 if let Err(_) = self.executor.park.park() {
477 loop {
478 let res = self.executor.borrow().enter(self.enter, || {
Thread 1 "worlddat" hit Breakpoint 1, <quinn::Driver as futures::future::Future>::poll (self=0x7fffffffc340)
at /home/icefox/.cargo/git/checkouts/quinn-572d2e5812b43165/1523bbe/quinn/src/lib.rs:641
641 let mut buf = [0; 64 * 1024];
642 let endpoint = &mut *self.0.borrow_mut();
643 if endpoint.driver.is_none() {
646 let now = micros_from(endpoint.epoch.elapsed());
649 match endpoint.socket.poll_recv_from(&mut buf) {
650 Ok(Async::Ready((n, addr))) => {
666 }
656 break;
667 while let Some((connection, event)) = endpoint.inner.poll() {
756 let mut blocked = false;
757 while !endpoint.outgoing.is_empty() {
777 while let Some(io) = endpoint.inner.poll_io(now) {
865 while let Ok(Async::Ready(_)) = endpoint.incoming.poll_ready() {
866 if let Some(x) = endpoint.inner.accept() {
872 break;
878 let _ = endpoint.incoming.poll_complete();
879 let mut fired = false;
881 match endpoint.timers.poll() {
882 Ok(Async::Ready(Some(Some((conn, timer))))) => {
894 if !fired {
898 Ok(Async::NotReady)
899 }
... more tokio junk returning from functions...
<tokio_current_thread::Entered<'a, P>>::block_on (self=0x7fffffffc4b8, future=...)
at /home/icefox/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-current-thread-0.1.3/src/lib.rs:480
480 });
482 match res {
483 Ok(Async::Ready(e)) => return Ok(e),
488 self.tick();
490 if let Err(_) = self.executor.park.park() {from quinn.
Ralith
commented on June 14, 2024
Thanks for the detailed traces! Although I still don't understand why you're not seeing any log messages (stepping into Endpoint::handle could be informative in that regard), there's a major clue here: every single trace passes through quinn/src/lib.rs:872, wherein an incoming connection is dropped because the application is not listening for one. In other words, it looks like the third component of the tuple returned by EndpointBuilder::bind, the Incoming stream, has been dropped.
Your start_listener function does seem to be properly spawning that stream, but start_outgoing drops its own; is it possible that you're confusing your client and server endpoints somehow? As an aside, there's not actually any need for two separate endpoints; you can use one endpoint to initiate and accept as many connections as you like concurrently.
from quinn.
icefoxen
commented on June 14, 2024
ahahaha it seems like the reason we're not seeing logs for the listener is 'cause I forgot I had to actually pass the logger to the EndpointBuilder. Sigh. Sorry about that.
Here's what it says when I try to connect to the listening port from the client:
Oct 31 08:13:10.805 TRCE logging from listener
Oct 31 08:13:10.808 DEBG dropping packet from unrecognized connection, header: Long { ty: 127, source_id: ConnectionId { len: 8, bytes: [149, 200, 94, 83, 54, 18, 47, 219, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] }, destination_id: ConnectionId { len: 18, bytes: [228, 87, 153, 133, 231, 243, 203, 184, 80, 48, 118, 101, 163, 30, 192, 184, 98, 235] }, number: 4010376301 }
Oct 31 08:13:11.010 DEBG dropping packet from unrecognized connection, header: Long { ty: 127, source_id: ConnectionId { len: 8, bytes: [149, 200, 94, 83, 54, 18, 47, 219, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] }, destination_id: ConnectionId { len: 18, bytes: [228, 87, 153, 133, 231, 243, 203, 184, 80, 48, 118, 101, 163, 30, 192, 184, 98, 235] }, number: 4010376302 }
Oct 31 08:13:11.411 DEBG dropping packet from unrecognized connection, header: Long { ty: 127, source_id: ConnectionId { len: 8, bytes: [149, 200, 94, 83, 54, 18, 47, 219, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] }, destination_id: ConnectionId { len: 18, bytes: [228, 87, 153, 133, 231, 243, 203, 184, 80, 48, 118, 101, 163, 30, 192, 184, 98, 235] }, number: 4010376303 }
Oct 31 08:13:12.212 DEBG dropping packet from unrecognized connection, header: Long { ty: 127, source_id: ConnectionId { len: 8, bytes: [149, 200, 94, 83, 54, 18, 47, 219, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] }, destination_id: ConnectionId { len: 18, bytes: [228, 87, 153, 133, 231, 243, 203, 184, 80, 48, 118, 101, 163, 30, 192, 184, 98, 235] }, number: 4010376304 }
Oct 31 08:13:13.815 DEBG dropping packet from unrecognized connection, header: Long { ty: 127, source_id: ConnectionId { len: 8, bytes: [149, 200, 94, 83, 54, 18, 47, 219, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] }, destination_id: ConnectionId { len: 18, bytes: [228, 87, 153, 133, 231, 243, 203, 184, 80, 48, 118, 101, 163, 30, 192, 184, 98, 235] }, number: 4010376305 }
Oct 31 08:13:17.015 DEBG dropping packet from unrecognized connection, header: Long { ty: 127, source_id: ConnectionId { len: 8, bytes: [149, 200, 94, 83, 54, 18, 47, 219, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] }, destination_id: ConnectionId { len: 18, bytes: [228, 87, 153, 133, 231, 243, 203, 184, 80, 48, 118, 101, 163, 30, 192, 184, 98, 235] }, number: 4010376306 }
Oct 31 08:13:23.417 DEBG dropping packet from unrecognized connection, header: Long { ty: 127, source_id: ConnectionId { len: 8, bytes: [149, 200, 94, 83, 54, 18, 47, 219, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] }, destination_id: ConnectionId { len: 18, bytes: [228, 87, 153, 133, 231, 243, 203, 184, 80, 48, 118, 101, 163, 30, 192, 184, 98, 235] }, number: 4010376307 }
I do drop the incoming stream for the "client" side (initiating an outgoing connection) because it doesn't need to listen for incoming connections... however if I can use one endpoint to both initiate and listen for connections then I might as well do that.
from quinn.
Ralith
commented on June 14, 2024
Looks like the dropped-stream thing was a red herring. Singlestepping is weird sometimes, I guess. Your problem is actually very simple: you never call EndpointBuilder::listen, so the endpoint is not configured to accept incoming connections! The log message could probably be tweaked to make this more obvious.
from quinn.
icefoxen
commented on June 14, 2024
Yep, adding the listen() call fixes this. Thank you!
from quinn.
Related Issues (20)
- 0-RTT packets can be lost due to race condition introduced along with Incoming HOT 1
- Debug formatting could be improved HOT 1
- GSO padding has high overhead for application datagrams larger than half MTU
- Consider more aggressive GSO batching
- stream sending buffer size and how much left HOT 3
- ECN interop failures HOT 3
- aggressive open_bi HOT 1
- Create my own AsyncUdpSocket HOT 1
- "SendableFrames was SendableFrames { acks: false, other: true }, but only ACKs have been written" HOT 11
- Black hole detection false-positives HOT 5
- Expose Packet Decoder？ HOT 2
- ReadExactError::FinishedEarly byte count is sometimes incorrect HOT 1
- How to receive data in blocking way HOT 3
- Inconsistent documentation on platform availability of `local_ip` HOT 3
- long running bi stream HOT 5
- seems like quinn 0.11 not working well under heavy load HOT 12
- API for awaiting for stream reset on the reader HOT 5
- build fails on Solaris HOT 1
- Rotation of Connection IDs HOT 5
- How to run insecure connection example? HOT 1
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from quinn.