quinn-rs / quinn

Async-friendly QUIC implementation in Rust
Apache License 2.0
3.76k stars 380 forks source link

Sending two Uni streams with data and receiving only one #1565

Closed serzhiio closed 1 year ago

serzhiio commented 1 year ago

Client creating two UNI streams and sending data to them. Both streams created and used at once. Server sees only one stream's data. I can't understand where is second stream's data? The log contains info that both streams came, but not all data.

P.S.: If i send two different streams(UNI+Bidi) i receive both of them.

Here is server log:

[2023-05-12T22:06:05.644008Z TRACE quinn_proto::connection] got Data packet (149 bytes) from 127.0.0.1:55002 using id e8997e456d6a1a50
[2023-05-12T22:06:05.644016Z TRACE quinn_proto::connection] recv; space=Data pn=2
[2023-05-12T22:06:05.644020Z TRACE tracing::span::active] -> recv;
[2023-05-12T22:06:05.644025Z TRACE quinn_proto::connection] frame; ty=ACK
[2023-05-12T22:06:05.644027Z TRACE quinn_proto::connection] got frame Ack(Ack { largest: 2, delay: 0, ecn: Some(EcnCounts { ect0: 3, ect1: 0, ce: 0 }), ranges: "[1..=2]" })
[2023-05-12T22:06:05.644034Z TRACE tracing::span::active] -> frame;
[2023-05-12T22:06:05.644038Z TRACE quinn_proto::connection::mtud] new MTU detected current_mtu=1326
[2023-05-12T22:06:05.644042Z TRACE tracing::span::active] <- frame;
[2023-05-12T22:06:05.644044Z TRACE tracing::span] -- frame;
[2023-05-12T22:06:05.644046Z TRACE quinn_proto::connection] frame; ty=STREAM
_______________________
[2023-05-12T22:06:05.644048Z TRACE quinn_proto::connection] got stream frame id=client unidirectional stream 0 offset=0 len=36 fin=true
[2023-05-12T22:06:05.644052Z TRACE tracing::span::active] -> frame;
[2023-05-12T22:06:05.644055Z TRACE tracing::span::active] <- frame;
[2023-05-12T22:06:05.644057Z TRACE tracing::span] -- frame;
[2023-05-12T22:06:05.644060Z TRACE quinn_proto::connection] frame; ty=STREAM
______________________
[2023-05-12T22:06:05.644061Z TRACE quinn_proto::connection] got stream frame id=client unidirectional stream 1 offset=0 len=72 fin=true
[2023-05-12T22:06:05.644063Z TRACE tracing::span::active] -> frame;
[2023-05-12T22:06:05.644066Z TRACE tracing::span::active] <- frame;
[2023-05-12T22:06:05.644068Z TRACE tracing::span] -- frame;
[2023-05-12T22:06:05.644070Z TRACE tracing::span::active] <- recv;
[2023-05-12T22:06:05.644072Z TRACE tracing::span] -- recv;
[2023-05-12T22:06:05.644075Z TRACE thread::eventloop::iouring::server] _found endpoint:0 for Identity(type:ServerUdp,flag:0,slave:0,master:0)
[2023-05-12T22:06:05.644078Z TRACE thread::eventloop::iouring::server::endpoint] UDP incoming_data Identity(type:ServerUdp,flag:0,slave:0,master:0), res=1525 | is_more: true
[2023-05-12T22:06:05.644081Z TRACE thread::eventloop::iouring::uni::client] RcvdMsgHdrStorage read_out(data=1525bytes)
[2023-05-12T22:06:05.644083Z TRACE thread::eventloop::iouring::uni::client] RecvMeta { len: 1389, stride: 1389, ecn: Some(Ect0), dst_ip: Some(127.0.0.1) }
[2023-05-12T22:06:05.644085Z TRACE thread::eventloop::iouring::uni::quic::quinn::instance] server incoming data to read len=1389bytes from 127.0.0.1:55002
[2023-05-12T22:06:05.644088Z TRACE quinn_proto::connection] got Data packet (1389 bytes) from 127.0.0.1:55002 using id e8997e456d6a1a50
[2023-05-12T22:06:05.644091Z TRACE quinn_proto::connection] recv; space=Data pn=3
[2023-05-12T22:06:05.644094Z TRACE tracing::span::active] -> recv;
[2023-05-12T22:06:05.644096Z TRACE quinn_proto::connection] frame; ty=PING
[2023-05-12T22:06:05.644098Z TRACE quinn_proto::connection] got frame Ping
[2023-05-12T22:06:05.644100Z TRACE tracing::span::active] -> frame;
[2023-05-12T22:06:05.644102Z TRACE tracing::span::active] <- frame;
[2023-05-12T22:06:05.644103Z TRACE tracing::span] -- frame;
[2023-05-12T22:06:05.644120Z TRACE tracing::span::active] <- recv;
[2023-05-12T22:06:05.644122Z TRACE tracing::span] -- recv;
[2023-05-12T22:06:05.644127Z TRACE thread::eventloop::iouring::uni::quic::quinn::instance] Server evt: StreamEvent!
[2023-05-12T22:06:05.644129Z TRACE thread::eventloop::iouring::uni::quic::quinn::instance] - opened unidirectional
__________________________
[2023-05-12T22:06:05.644135Z DEBUG server::app] Worker:0 CH:None size:36bytes data: [0, 3, 0, 0, 0, 5, 251, 134, 79, 188, 88, 27, 0, 1, 0, 0, 0, 14, 100, 117, 109, 109, 121, 95, 101, 120, 99, 104, 97, 110, 103, 101, 0, 2, 0, 1]
[2023-05-12T22:06:05.644143Z TRACE thread::eventloop::iouring::uni::quic::quinn::instance] - - should transmit
[2023-05-12T22:06:05.644147Z TRACE quinn_proto::connection::packet_builder] send; space=Data pn=3
[2023-05-12T22:06:05.644151Z TRACE quinn_proto::connection] ACK ArrayRangeSet([2..4]), Delay = 0us
[2023-05-12T22:06:05.644155Z TRACE quinn_proto::connection::streams::state] MAX_STREAMS (Uni) value=101
[2023-05-12T22:06:05.644160Z TRACE tracing::span] -- send;
[2023-05-12T22:06:05.644163Z TRACE quinn_proto::connection] sending 37 bytes in 1 datagrams
[2023-05-12T22:06:05.644166Z TRACE quinn_proto::connection::packet_builder] send; space=Data pn=4
[2023-05-12T22:06:05.644169Z TRACE quinn_proto::connection::packet_builder] PADDING * 1362
[2023-05-12T22:06:05.644172Z TRACE tracing::span] -- send;
[2023-05-12T22:06:05.644174Z TRACE quinn_proto::connection] writing MTUD probe probe_size=1389
[2023-05-12T22:06:05.644177Z TRACE quinn_proto::connection] sending 1389 bytes in 1 datagrams
Ralith commented 1 year ago

Those logs seem to indicate that you've received two streams in full at about the same time. What does your code look like?

serzhiio commented 1 year ago

It looks like twqo packets aggregated together comes at once and i think it could be only one at a time. So the reason for this bahavior is likely this part of my code:

match stream_event {
    StreamEvent::Opened { dir } => {
         crate::log::trace!("- opened {dir}");
         remote_stream = conn.inner.streams().accept(dir).unwrap();
    }
}

maybe this? :

while let Some(remote_stream) = conn.inner.streams().accept(dir) {
    ...
}
Ralith commented 1 year ago

There is nothing specifically wrong with those small fragments of code. Maybe try making a self-contained minimal reproduction?

serzhiio commented 1 year ago

The reason of my problem was expecting only one Stream when several could come in one packet and I thought that i will receive Opened event for each stream separately using while let Some(event) = conn.poll() {...}.

How it was:

StreamEvent::Opened { dir } => {
    let remote_stream = conn.streams().accept(dir).unwrap();
}

How it work:

StreamEvent::Opened { dir } => {
    while let Some(remote_stream) = conn.streams().accept(dir) {
        ...
    }
}

Sorry for disturbing you, the library still have a lot of unknow's for me especially considering io_uring.

djc commented 1 year ago

Want to propose any documentation improvements that would have made this more obvious?

serzhiio commented 1 year ago

I see that StreamEvent already have such explanation here and .accept(dir) here.