Requests with body to NGINX hang when request buffering is enabled

[lilongyan-huawei]

when the size of request body > 8192(2*page size) , buf->last will identically equal to buf->end.

[ghedo]

You really need to provide more information on what the problem you are reporting is, because from what you posted it's really not clear. Like, what is the expected behavior, and what is the behavior you are seeing instead? Describing a way to reproduce the problem would also be helpful, thanks.

[lilongyan-huawei]

You really need to provide more information on what the problem you are reporting is, because from what you posted it's really not clear. Like, what is the expected behavior, and what is the behavior you are seeing instead? Describing a way to reproduce the problem would also be helpful, thanks.

the bug's description: use quiche-nginx as server. when I send a request ( the body > 8192(2*page size) bytes), it will be failed.

You can test by following this procedure:

1. Quic server: Deploy Quiche on Nginx, the version of Nginx is nginx 1.16.1, use the patch that quiche suppot.
2. Configure a backend server use proxy_pass in conf/nginx.conf
3. Quic Client: Any one client that support http3. for example: curl --http3
4. send a post request from client. and the body's length is greater than client_body_buffer_size(default value is 8192 bytes, it can be configured in nginx.conf), you will send failed. because the patch(quiche support) of nginx1.16.1 has bug: you can't post a request whose body length is greater than client_body_buffer_size.

I figured out the reason: firstly, the length of request body is greater than client_body_buffer_size(default value is 8192 bytes), nginx will create a buffer that has no real space. buf->last will identically equal to buf->end , because both of them are 0 .

when the function (ngx_http_v3_process_request_body) process the request body, buf->last will identically equal to buf->end, so this fuction will return NGX_AGAIN and reading 0 bytes

[ghedo]

Ok, thanks. Just to double check, did you disable request buffering in NGINX (proxy_request_buffering off;)? I can reproduce the problem now but only when request buffering is enabled.

This is actually a known problem as we don't fully support request buffering for HTTP/3 right now, so we recommend disabling it for now.

[lilongyan-huawei]

Ok, thanks. Just to double check, did you disable request buffering in NGINX (proxy_request_buffering off;)? I can reproduce the problem now but only when request buffering is enabled.

This is actually a known problem as we don't fully support request buffering for HTTP/3 right now, so we recommend disabling it for now.

the value of proxy_request_buffering is default (on ?);
Since it is not supported, are there plans to support this feature? and When will it be supported ? many thanks.

[ghedo]

It's definitely something we should fix at some point, though we don't really have an estimate right now as it's not very high priority (we don't use this option ourselves in production). Would definitely welcome patches though, so I'll leave this ticket open if anyone wants to work on this before we get to it.

[lilongyan-huawei]

It's definitely something we should fix at some point, though we don't really have an estimate right now as it's not very high priority (we don't use this option ourselves in production). Would definitely welcome patches though, so I'll leave this ticket open if anyone wants to work on this before we get to it.

Ok, thanks. but how do you solve the following problem? With buffering disabled, the request body is sent to the proxy server as soon as the request is received.In this case, if Nginx has already started sending the request body, the request cannot be passed to the Next Server.

[lilongyan-huawei]

It's definitely something we should fix at some point, though we don't really have an estimate right now as it's not very high priority (we don't use this option ourselves in production). Would definitely welcome patches though, so I'll leave this ticket open if anyone wants to work on this before we get to it. @ghedo I disable request buffering in NGINX (proxy_request_buffering off;), but it would not work. Open the logs/error.log, found something wrong. Could you help me to see what's wrong i did ? thank you.

2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 handler 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 rx pkt Short dcid=e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 key_phase=false len=780 pn=16 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 rx frm STREAM id=0 off=12868 len=757 fin=false 2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 handler 2020/10/09 14:45:47 [debug] 318862#0: quiche::h3: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 stream id 0 is readable 2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 event stream:0 ev:1 2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 process data 2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 process request body 2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 reading 8192 bytes of request body 2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 read 757 bytes of request body 2020/10/09 14:45:47 [debug] 318862#0: 8650 http run request: "/upload/tribe?fileName=test.abcd" 2020/10/09 14:45:47 [debug] 318862#0: 8650 http upstream read request handler 2020/10/09 14:45:47 [debug] 318862#0: 8650 http upstream send request 2020/10/09 14:45:47 [debug] 318862#0: 8650 http upstream send request body 2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 read unbuffered request body 2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 filter request body 2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 read unbuffered request body 2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 filter request body 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Short dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d key_phase=false len=21 pn=20 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=17 blocks=[0..16] 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=19.424719ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=701 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=6.69536ms recent_delivered_packet_sent_time=7.041039ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: 8650 http3 handler 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 loss detection timeout expired 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=25.67285ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 1, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=701 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=26.909595ms recent_delivered_packet_sent_time=27.255362ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Handshake version=ff00001d dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d scid=e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 len=23 pn=5 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=3367 blocks=[0..2] 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm PING 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=27.066443ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=773 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=27.007173ms recent_delivered_packet_sent_time=27.352785ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 loss detection timeout expired 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=52.733823ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 2] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=773 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=54.280836ms recent_delivered_packet_sent_time=54.626841ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Short dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d key_phase=false len=531 pn=21 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=5987 blocks=[0..16] 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm HANDSHAKE_DONE 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm CRYPTO off=0 len=476 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm STREAM id=3 off=0 len=24 fin=false 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=78.129209ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 1] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=1326 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=54.643121ms recent_delivered_packet_sent_time=54.989243ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Short dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d key_phase=false len=27 pn=22 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=6024 blocks=[0..16] 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm STREAM id=7 off=0 len=1 fin=false 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=77.857327ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=1375 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=54.916351ms recent_delivered_packet_sent_time=55.26237ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 loss detection timeout expired 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=105.403506ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 2, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=1375 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=133.215651ms recent_delivered_packet_sent_time=133.561527ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Handshake version=ff00001d dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d scid=e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 len=25 pn=6 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=16657 blocks=[0..2] 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm PING 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=132.964983ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 1, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=1449 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=133.411281ms recent_delivered_packet_sent_time=133.756986ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Handshake version=ff00001d dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d scid=e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 len=25 pn=7 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=16684 blocks=[0..2] 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm PING 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=132.845439ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=1523 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=133.527177ms recent_delivered_packet_sent_time=133.872779ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 loss detection timeout expired 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=211.070161ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 2] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=1523 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=266.996408ms recent_delivered_packet_sent_time=267.342692ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Short dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d key_phase=false len=533 pn=23 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=32574 blocks=[0..16] 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm HANDSHAKE_DONE 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm CRYPTO off=0 len=476 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm STREAM id=3 off=0 len=24 fin=false 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=289.468861ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 1] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=2078 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=267.36364ms recent_delivered_packet_sent_time=267.709822ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Short dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d key_phase=false len=29 pn=24 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=32618 blocks=[0..16] 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm STREAM id=7 off=0 len=1 fin=false 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=289.2373ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=2129 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=267.589177ms recent_delivered_packet_sent_time=267.935025ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 loss detection timeout expired 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=423.159547ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 2, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=2129 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=557.029071ms recent_delivered_packet_sent_time=557.374971ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Handshake version=ff00001d dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d scid=e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 len=25 pn=8 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=69633 blocks=[0..2] 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm PING 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=556.89497ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 1, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=2203 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=557.263835ms recent_delivered_packet_sent_time=557.60994ms app_limited_at_pkt=3949
2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Handshake version=ff00001d dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d scid=e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 len=25 pn=9 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=69664 blocks=[0..2] 2020/10/09 14:45:47 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm PING 2020/10/09 14:45:47 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=556.778149ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=2277 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=557.375367ms recent_delivered_packet_sent_time=557.72102ms app_limited_at_pkt=3949
2020/10/09 14:45:48 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 loss detection timeout expired 2020/10/09 14:45:48 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=845.567484ms latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 2] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=2277 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=1.115299278s recent_delivered_packet_sent_time=1.11564517s app_limited_at_pkt=3949
2020/10/09 14:45:48 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Short dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d key_phase=false len=533 pn=25 2020/10/09 14:45:48 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=138606 blocks=[0..16] 2020/10/09 14:45:48 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm HANDSHAKE_DONE 2020/10/09 14:45:48 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm CRYPTO off=0 len=476 2020/10/09 14:45:48 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm STREAM id=3 off=0 len=24 fin=false 2020/10/09 14:45:48 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=1.13521064s latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 1] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=2832 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=1.115503706s recent_delivered_packet_sent_time=1.115849443s app_limited_at_pkt=3949
2020/10/09 14:45:48 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Short dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d key_phase=false len=29 pn=26 2020/10/09 14:45:48 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=138630 blocks=[0..16] 2020/10/09 14:45:48 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm STREAM id=7 off=0 len=1 fin=false 2020/10/09 14:45:48 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=1.135054774s latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=2883 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=1.115660252s recent_delivered_packet_sent_time=1.116005974s app_limited_at_pkt=3949
2020/10/09 14:45:49 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 loss detection timeout expired 2020/10/09 14:45:49 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=1.692621767s latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 2, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=2883 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=2.251508586s recent_delivered_packet_sent_time=2.251855014s app_limited_at_pkt=3949
2020/10/09 14:45:49 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Handshake version=ff00001d dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d scid=e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 len=25 pn=10 2020/10/09 14:45:49 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=281444 blocks=[0..2] 2020/10/09 14:45:49 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm PING 2020/10/09 14:45:49 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=2.250671533s latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 1, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=2957 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=2.251682803s recent_delivered_packet_sent_time=2.252028532s app_limited_at_pkt=3949
2020/10/09 14:45:49 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Handshake version=ff00001d dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d scid=e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 len=25 pn=11 2020/10/09 14:45:49 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=281465 blocks=[0..2] 2020/10/09 14:45:49 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm PING 2020/10/09 14:45:49 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=2.250483274s latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=3031 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=2.25187104s recent_delivered_packet_sent_time=2.252216818s app_limited_at_pkt=3949
2020/10/09 14:45:51 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 loss detection timeout expired 2020/10/09 14:45:51 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=3.386004164s latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 2] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=3031 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=4.503161171s recent_delivered_packet_sent_time=4.503507053s app_limited_at_pkt=3949
2020/10/09 14:45:51 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Short dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d key_phase=false len=533 pn=27 2020/10/09 14:45:51 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=562087 blocks=[0..16] 2020/10/09 14:45:51 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm HANDSHAKE_DONE 2020/10/09 14:45:51 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm CRYPTO off=0 len=476 2020/10/09 14:45:51 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm STREAM id=3 off=0 len=24 fin=false 2020/10/09 14:45:51 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=4.522012457s latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 1] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=3586 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=4.503322419s recent_delivered_packet_sent_time=4.503668073s app_limited_at_pkt=3949
2020/10/09 14:45:51 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx pkt Short dcid=4fddbe310578a86e2d1545f0f379e9338b5d325d key_phase=false len=29 pn=28 2020/10/09 14:45:51 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm ACK delay=562108 blocks=[0..16] 2020/10/09 14:45:51 [debug] 318862#0: quiche: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 tx frm STREAM id=7 off=0 len=1 fin=false 2020/10/09 14:45:51 [debug] 318862#0: quiche::recovery: e1e89d672162dd7a3399ae5d16cfec21d2dc14c1 timer=4.5218863s latest_rtt=345.246µs srtt=Some(459.416µs) min_rtt=345.246µs rttvar=201.621µs loss_time=[None, None, None] loss_probes=[0, 0, 0] cwnd=14687 ssthresh=18446744073709551615 bytes_in_flight=3637 app_limited=true congestion_recovery_start_time=None delivered=3949 delivered_time=4.503447844s recent_delivered_packet_sent_time=4.503793486s app_limited_at_pkt=3949