Comments (10)
larseggert
commented on July 30, 2024
Thanks for the report! My migration code is pretty old and hasn't really been updates for recent draft versions. I added code in 8d8fcea to log IP addresses and ports for packets, so that should make debugging this a bit easier.
from quant.
kenmcmil
commented on July 30, 2024
Thanks. I got another trace, but unfortunately the TX addresses are not coming out correctly. Here's the log. The packet coming from the new address is 1rtt packet number 1, which is not the highest packet number at the time. Initial packet number 3 is sent incorrectly to the new address.
0.032 q_init quic.c:507 quant/socket 0.0.16/153c932 with libev/epoll 4.22 ready
q_init quic.c:508 submit bug reports at https://github.com/NTAP/quant/issues
0.034 q_init quic.c:527 debug build, storing fuzzer corpus data
q_bind quic.c:362 binding serv socket on port 4443
init_rec recovery.c:527 in_flight=0, cwnd=12000, ssthresh=0, srtt=0.000000, rttvar=0.000000
new_conn conn.c:1285 serv conn ? on port 4443 created
new_conn conn.c:1287 serv conn ? state conn_clsd -> conn_idle
q_bind quic.c:364 bound serv socket on port 4443
main server.c:239 server waiting on lo port 4443
0.175 rx_pkts conn.c:892 new serv conn on port 4443 from 127.0.0.1:4988 w/cid=0:0000000000000001
init_rec recovery.c:527 in_flight=0, cwnd=12000, ssthresh=0, srtt=0.000000, rttvar=0.000000
new_conn conn.c:1285 serv conn 0:0000000000000001 on port 4443 created
new_conn conn.c:1287 serv conn 0:0000000000000001 state conn_clsd -> conn_idle
0.176 log_pkt pkt.c:121 RX from=127.0.0.1:4988 len=1216 0xff=Initial vers=0xff00000f dcid=0000000000000001 scid=000000000000000d tok=06 len=1206 nr=0
rx_pkt conn.c:655 supporting clnt-requested vers 0xff00000f
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=243 [seq]
dec_frames frame.c:894 PADDING len=938
rx_pkt conn.c:680 serv conn 0:0000000000000001 state conn_idle -> conn_opng
update_act_scid conn.c:478 hshk switch to scid 0:5656aa3d1039d0e1 for serv conn (was 0:0000000000000001)
on_ch tls.c:306 SNI =
on_ch tls.c:309 ALPN =
chk_tp tls.c:471 initial_max_stream_data_bidi_local = 8192
chk_tp tls.c:483 initial_max_data = 16384
chk_tp tls.c:500 idle_timeout = 60
chk_tp tls.c:478 initial_max_stream_data_bidi_remote = 8192
chk_tp tls.c:465 initial_max_stream_data_uni = 8192
0.178 rx_crypto conn.c:558 serv conn 0:5656aa3d1039d0e1 state conn_opng -> conn_estb
tx conn.c:429 data TX on serv conn 0:5656aa3d1039d0e1 strm -4 w/1 pkt in queue
enc_pkt pkt.c:393 hshk switch to scid 0:dbb087a6934f5ce4 for serv conn (was 0:5656aa3d1039d0e1)
update_act_scid conn.c:478 hshk switch to scid 0:dbb087a6934f5ce4 for serv conn (was 0:5656aa3d1039d0e1)
0.179 log_pkt pkt.c:174 TX to=0.0.0.0:0 0xff=Initial vers=0xff00000f dcid=000000000000000d scid=dbb087a6934f5ce4 tok=6afa61e94f25936bbfa3b78cb808a0e80829445f9be5af75d8becf6f193ce6cc5656aa3d1039d0e1 len=0 nr=0
enc_ack_frame frame.c:1170 ACK lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
enc_padding_frame frame.c:1098 PADDING len=97
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=155
on_pkt_sent recovery.c:284 in_flight=299, cwnd=12000, ssthresh=0, srtt=0.000000, rttvar=0.000000
log_sent_pkts conn.c:229 epoch 0 unacked: *0
tx conn.c:429 data TX on serv conn 0:dbb087a6934f5ce4 strm -2 w/2 pkts in queue
0.179 log_pkt pkt.c:184 TX to=0.0.0.0:0 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=dbb087a6934f5ce4 len=0 nr=0
enc_padding_frame frame.c:1098 PADDING len=103
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=1108
on_pkt_sent recovery.c:284 in_flight=1551, cwnd=12000, ssthresh=0, srtt=0.000000, rttvar=0.000000
0.179 log_pkt pkt.c:184 TX to=0.0.0.0:0 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=dbb087a6934f5ce4 len=0 nr=1
enc_padding_frame frame.c:1098 PADDING len=103
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=1108 len=292
on_pkt_sent recovery.c:284 in_flight=1987, cwnd=12000, ssthresh=0, srtt=0.000000, rttvar=0.000000
log_sent_pkts conn.c:229 epoch 0 unacked: *0
log_sent_pkts conn.c:229 epoch 2 unacked: *0 *1
coalesce pkt.c:223 coalescing 0xfd len 436 behind 0xff len 299
0.350 log_pkt pkt.c:139 RX from=127.0.0.1:4988 len=56 0x30=Short kyph=0 dcid=dbb087a6934f5ce4 nr=0
rx_pkts conn.c:972 received invalid 56-byte 0x30-type pkt, ignoring
0.376 on_ld_alarm recovery.c:199 handshake RTX #1 on serv conn 0:dbb087a6934f5ce4
detect_lost_pkts recovery.c:153 pkt 0 considered lost
detect_lost_pkts recovery.c:160 in_flight=1688, cwnd=12000, ssthresh=0, srtt=0.000000, rttvar=0.000000
detect_lost_pkts recovery.c:153 pkt 0 considered lost
detect_lost_pkts recovery.c:160 in_flight=436, cwnd=12000, ssthresh=0, srtt=0.000000, rttvar=0.000000
detect_lost_pkts recovery.c:153 pkt 1 considered lost
detect_lost_pkts recovery.c:160 in_flight=0, cwnd=12000, ssthresh=0, srtt=0.000000, rttvar=0.000000
detect_lost_pkts recovery.c:183 in_flight=0, cwnd=6000, ssthresh=6000, srtt=0.000000, rttvar=0.000000
tx conn.c:429 data TX on serv conn 0:dbb087a6934f5ce4 strm -4 w/1 pkt in queue
0.376 log_pkt pkt.c:174 TX to=0.0.0.0:0 0xff=Initial vers=0xff00000f dcid=000000000000000d scid=dbb087a6934f5ce4 tok=6afa61e94f25936bbfa3b78cb808a0e80829445f9be5af75d8becf6f193ce6cc5656aa3d1039d0e1 len=274 nr=1
enc_ack_frame frame.c:1170 ACK lg=0 delay=25109 (200872 usec) cnt=0 block=0 [0]
enc_padding_frame frame.c:1098 PADDING len=90
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=155 [RTX]
on_pkt_sent recovery.c:284 in_flight=299, cwnd=6000, ssthresh=6000, srtt=0.000000, rttvar=0.000000
log_sent_pkts conn.c:229 epoch 0 unacked: *0 *1
log_sent_pkts conn.c:229 epoch 2 unacked: *0 *1
tx conn.c:429 data TX on serv conn 0:dbb087a6934f5ce4 strm -2 w/2 pkts in queue
0.377 log_pkt pkt.c:184 TX to=0.0.0.0:0 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=dbb087a6934f5ce4 len=1228 nr=2
enc_padding_frame frame.c:1098 PADDING len=99
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=1108 [RTX]
on_pkt_sent recovery.c:284 in_flight=1551, cwnd=6000, ssthresh=6000, srtt=0.000000, rttvar=0.000000
0.377 log_pkt pkt.c:184 TX to=0.0.0.0:0 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=dbb087a6934f5ce4 len=412 nr=3
enc_padding_frame frame.c:1098 PADDING len=98
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=1108 len=292 [RTX]
on_pkt_sent recovery.c:284 in_flight=1987, cwnd=6000, ssthresh=6000, srtt=0.000000, rttvar=0.000000
log_sent_pkts conn.c:229 epoch 0 unacked: *0 *1
log_sent_pkts conn.c:229 epoch 2 unacked: *0 *1 *2 *3
coalesce pkt.c:223 coalescing 0xfd len 436 behind 0xff len 299
0.663 log_pkt pkt.c:131 RX from=127.0.0.1:4988 len=109 0xfd=Handshake vers=0xff00000f dcid=dbb087a6934f5ce4 scid=000000000000000d len=101 nr=0
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=52 [seq]
dec_ack_frame frame.c:391 ACK lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
update_rtt recovery.c:318 in_flight=1987, cwnd=6000, ssthresh=6000, srtt=0.487417, rttvar=0.243708
on_pkt_acked recovery.c:461 0 was RTX'ed as 2
dec_ack_frame frame.c:391 ACK lg=1 delay=0 (0 usec) cnt=0 block=0 [1]
update_rtt recovery.c:318 in_flight=1987, cwnd=6000, ssthresh=6000, srtt=0.487417, rttvar=0.182781
on_pkt_acked recovery.c:461 1 was RTX'ed as 3
dec_frames frame.c:894 PADDING len=15
tx conn.c:429 data TX on serv conn 0:dbb087a6934f5ce4 strm -4 w/1 pkt in queue
0.663 log_pkt pkt.c:174 TX to=0.0.0.0:0 0xff=Initial vers=0xff00000f dcid=000000000000000d scid=dbb087a6934f5ce4 tok=6afa61e94f25936bbfa3b78cb808a0e80829445f9be5af75d8becf6f193ce6cc5656aa3d1039d0e1 len=274 nr=2
enc_ack_frame frame.c:1170 ACK lg=0 delay=60927 (487416 usec) cnt=0 block=0 [0]
enc_padding_frame frame.c:1098 PADDING len=90
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=155 [RTX]
on_pkt_sent recovery.c:284 in_flight=2286, cwnd=6000, ssthresh=6000, srtt=0.487417, rttvar=0.182781
log_sent_pkts conn.c:229 epoch 0 unacked: *0 *1 *2
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3
tx conn.c:429 data TX on serv conn 0:dbb087a6934f5ce4 strm -2 w/2 pkts in queue
0.663 log_pkt pkt.c:184 TX to=0.0.0.0:0 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=dbb087a6934f5ce4 len=1228 nr=4
enc_ack_frame frame.c:1170 ACK lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
enc_padding_frame frame.c:1098 PADDING len=94
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=1108 [RTX]
on_pkt_sent recovery.c:284 in_flight=3538, cwnd=6000, ssthresh=6000, srtt=0.487417, rttvar=0.182781
0.663 log_pkt pkt.c:184 TX to=0.0.0.0:0 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=dbb087a6934f5ce4 len=412 nr=5
enc_ack_frame frame.c:1170 ACK lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
enc_padding_frame frame.c:1098 PADDING len=93
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=1108 len=292 [RTX]
on_pkt_sent recovery.c:284 in_flight=3974, cwnd=6000, ssthresh=6000, srtt=0.487417, rttvar=0.182781
log_sent_pkts conn.c:229 epoch 0 unacked: *0 *1 *2
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3 *4 *5
0.664 log_pkt pkt.c:192 TX to=0.0.0.0:0 0x32=Short kyph=0 dcid=000000000000000d nr=0
enc_new_token_frame frame.c:1497 NEW_TOKEN len=40 tok=6afa61e94f25936bbfa3b78cb808a0e80829445f9be5af75d8becf6f193ce6cc5656aa3d1039d0e1
enc_new_cid_frame frame.c:1476 NEW_CONNECTION_ID seq=1 len=8 cid=1:3e3e3b3915909a1a tok=3e1d4de4fc9f076ba298f1c5e5d406c2
on_pkt_sent recovery.c:284 in_flight=4069, cwnd=6000, ssthresh=6000, srtt=0.487417, rttvar=0.182781
coalesce pkt.c:223 coalescing 0xfd len 436 behind 0xff len 299
coalesce pkt.c:223 coalescing 0x32 len 95 behind 0xfd len 735
0.752 log_pkt pkt.c:139 RX from=127.0.0.1:4988 len=41 0x30=Short kyph=0 dcid=dbb087a6934f5ce4 nr=2
new_stream stream.c:101 serv conn 0:dbb087a6934f5ce4 strm 4 (bidir, clnt) state strm_idle -> strm_open
log_stream_or_crypto_frame frame.c:113 STREAM 0x16=LEN|OFF id=4/20 off=7/65535 len=8 coff=8/393210 [ooo]
dec_frames frame.c:894 PADDING len=15
0.777 ack_alarm pn.c:56 ACK timer fired on serv conn 0:dbb087a6934f5ce4 epoch 3
0.777 log_pkt pkt.c:192 TX to=127.0.0.1:4988 0x32=Short kyph=0 dcid=000000000000000d nr=1
enc_ack_frame frame.c:1170 ACK lg=2 delay=3169 (25352 usec) cnt=0 block=0 [2]
1.225 rx_pkts conn.c:926 pkt came from new peer 127.0.0.1:4987, probing
1.225 log_pkt pkt.c:139 RX from=127.0.0.1:4987 len=72 0x30=Short kyph=0 dcid=dbb087a6934f5ce4 nr=1
log_stream_or_crypto_frame frame.c:113 STREAM 0x16=LEN|OFF id=4/20 off=15/65535 len=17 coff=25/393210 [ooo]
dec_ack_frame frame.c:391 ACK lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
update_rtt recovery.c:318 in_flight=4069, cwnd=6000, ssthresh=6000, srtt=0.496760, rttvar=0.155771
dec_ack_frame frame.c:391 ACK lg=1 delay=0 (0 usec) cnt=0 block=0 [1]
update_rtt recovery.c:318 in_flight=3974, cwnd=6000, ssthresh=6000, srtt=0.490644, rttvar=0.129060
dec_frames frame.c:906 addtl stream or crypto frame at pos 44, copy
log_stream_or_crypto_frame frame.c:113 STREAM 0x16=LEN|OFF id=4/20 off=32/65535 len=8 coff=33/393210 [ooo]
dec_frames frame.c:894 PADDING len=15
tx conn.c:429 data TX on serv conn 0:dbb087a6934f5ce4 strm -4 w/1 pkt in queue
1.225 log_pkt pkt.c:174 TX to=0.0.0.0:0 0xff=Initial vers=0xff00000f dcid=000000000000000d scid=dbb087a6934f5ce4 tok= len=274 nr=3
enc_ack_frame frame.c:1170 ACK lg=0 delay=131196 (1049568 usec) cnt=0 block=0 [0]
enc_padding_frame frame.c:1098 PADDING len=90
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=155 [RTX]
on_pkt_sent recovery.c:284 in_flight=4273, cwnd=6000, ssthresh=6000, srtt=0.490644, rttvar=0.129060
tx_stream_data conn.c:324 cwnd limit reached at in_flight 4273 + 2020 > 6000
log_sent_pkts conn.c:229 epoch 0 unacked: *0 *1 *2 *3
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3 *4 *5
1.225 log_pkt pkt.c:192 TX to=0.0.0.0:0 0x33=Short kyph=0 dcid=000000000000000d nr=2
enc_ack_frame frame.c:1170 ACK lg=1 delay=0 (0 usec) cnt=0 block=0 [1]
enc_path_challenge_frame frame.c:1447 PATH_CHALLENGE data=e2e4f1d70ee917a6
on_pkt_sent recovery.c:284 in_flight=4313, cwnd=6000, ssthresh=6000, srtt=0.490644, rttvar=0.129060
from quant.
larseggert
commented on July 30, 2024
Are you sure you are on the latest version? I fixed the 0.0.0.0 issue
from quant.
kenmcmil
commented on July 30, 2024
Your're right. Here's a trace that shows the correct TX addresses. At 3.419, the server receives a packet from port 4988 without a highest packet number and it switches to this port for transmissions.
0.032 q_init quic.c:507 quant/socket 0.0.16/e2c7fbf with libev/epoll 4.22 ready
q_init quic.c:508 submit bug reports at https://github.com/NTAP/quant/issues
0.034 q_init quic.c:527 debug build, storing fuzzer corpus data
q_bind quic.c:362 binding serv socket on port 4443
init_rec recovery.c:558 in_flight=0 (+0), cwnd=12000 (+12000), ssthresh=0 (+0), srtt=0.000000 (+0.000000), rttvar=0.000000 (+0.000000)
new_conn conn.c:1311 serv conn ? on port 4443 created
new_conn conn.c:1313 serv conn ? state conn_clsd -> conn_idle
q_bind quic.c:364 bound serv socket on port 4443
main server.c:239 server waiting on lo port 4443
0.184 rx_pkts conn.c:918 new serv conn on port 4443 from 127.0.0.1:4987 w/cid=0:0000000000000009
init_rec recovery.c:558 in_flight=0 (+0), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.000000 (+0.000000), rttvar=0.000000 (+0.000000)
new_conn conn.c:1311 serv conn 0:0000000000000009 on port 4443 created
new_conn conn.c:1313 serv conn 0:0000000000000009 state conn_clsd -> conn_idle
0.184 log_pkt pkt.c:123 RX from=127.0.0.1:4987 len=1216 0xff=Initial vers=0xff00000f dcid=0000000000000009 scid=000000000000000d tok=625e7f len=1204 nr=0
rx_pkt conn.c:680 supporting clnt-requested vers 0xff00000f
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=243 [seq]
dec_frames frame.c:895 PADDING len=936
rx_pkt conn.c:705 serv conn 0:0000000000000009 state conn_idle -> conn_opng
update_act_scid conn.c:503 hshk switch to scid 0:7f12d0477ff88495 for serv conn (was 0:0000000000000009)
0.185 on_ch tls.c:306 SNI =
on_ch tls.c:309 ALPN =
chk_tp tls.c:471 initial_max_stream_data_bidi_local = 8192
chk_tp tls.c:483 initial_max_data = 16384
chk_tp tls.c:500 idle_timeout = 60
chk_tp tls.c:478 initial_max_stream_data_bidi_remote = 8192
chk_tp tls.c:465 initial_max_stream_data_uni = 8192
0.188 rx_crypto conn.c:583 serv conn 0:7f12d0477ff88495 state conn_opng -> conn_estb
tx conn.c:429 data TX on serv conn 0:7f12d0477ff88495 strm -4 w/1 pkt in queue
enc_pkt pkt.c:395 hshk switch to scid 0:5cef812761a8eb78 for serv conn (was 0:7f12d0477ff88495)
update_act_scid conn.c:503 hshk switch to scid 0:5cef812761a8eb78 for serv conn (was 0:7f12d0477ff88495)
0.188 log_pkt pkt.c:176 TX to=127.0.0.1:4987 0xff=Initial vers=0xff00000f dcid=000000000000000d scid=5cef812761a8eb78 tok=0573f52296eaf6a20abb89f62880f0674a6617cf6628ef6e8de788290051967b7f12d0477ff88495 len=0 nr=0
enc_ack_frame frame.c:1171 ACK lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
enc_padding_frame frame.c:1099 PADDING len=97
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=155
on_pkt_sent recovery.c:311 in_flight=299 (+299), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.000000 (+0.000000), rttvar=0.000000 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.200000 sec on serv conn 0:5cef812761a8eb78
log_sent_pkts conn.c:229 epoch 0 unacked: *0
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm -2 w/2 pkts in queue
0.188 log_pkt pkt.c:186 TX to=127.0.0.1:4987 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=5cef812761a8eb78 len=0 nr=0
enc_padding_frame frame.c:1099 PADDING len=103
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=1108
on_pkt_sent recovery.c:311 in_flight=1551 (+1252), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.000000 (+0.000000), rttvar=0.000000 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.200000 sec on serv conn 0:5cef812761a8eb78
0.188 log_pkt pkt.c:186 TX to=127.0.0.1:4987 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=5cef812761a8eb78 len=0 nr=1
enc_padding_frame frame.c:1099 PADDING len=103
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=1108 len=292
on_pkt_sent recovery.c:311 in_flight=1987 (+436), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.000000 (+0.000000), rttvar=0.000000 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.200000 sec on serv conn 0:5cef812761a8eb78
log_sent_pkts conn.c:229 epoch 0 unacked: *0
log_sent_pkts conn.c:229 epoch 2 unacked: *0 *1
coalesce pkt.c:225 coalescing 0xfd len 436 behind 0xff len 299
0.383 on_ld_alarm recovery.c:226 crypto RTX #1 on serv conn 0:5cef812761a8eb78
detect_lost_pkts recovery.c:171 pkt 0 considered lost
detect_lost_pkts recovery.c:210 in_flight=1688 (-299), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.000000 (+0.000000), rttvar=0.000000 (+0.000000)
detect_lost_pkts recovery.c:171 pkt 0 considered lost
detect_lost_pkts recovery.c:171 pkt 1 considered lost
detect_lost_pkts recovery.c:210 in_flight=0 (-1688), cwnd=6000 (-6000), ssthresh=6000 (+6000), srtt=0.000000 (+0.000000), rttvar=0.000000 (+0.000000)
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm -4 w/1 pkt in queue
0.384 log_pkt pkt.c:176 TX to=127.0.0.1:4987 0xff=Initial vers=0xff00000f dcid=000000000000000d scid=5cef812761a8eb78 tok=0573f52296eaf6a20abb89f62880f0674a6617cf6628ef6e8de788290051967b7f12d0477ff88495 len=274 nr=1
enc_padding_frame frame.c:1099 PADDING len=98
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=155 [RTX]
on_pkt_sent recovery.c:311 in_flight=299 (+299), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.000000 (+0.000000), rttvar=0.000000 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.400000 sec on serv conn 0:5cef812761a8eb78
log_sent_pkts conn.c:229 epoch 0 unacked: *0 *1
log_sent_pkts conn.c:229 epoch 2 unacked: *0 *1
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm -2 w/2 pkts in queue
0.384 log_pkt pkt.c:186 TX to=127.0.0.1:4987 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=5cef812761a8eb78 len=1228 nr=2
enc_padding_frame frame.c:1099 PADDING len=99
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=1108 [RTX]
on_pkt_sent recovery.c:311 in_flight=1551 (+1252), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.000000 (+0.000000), rttvar=0.000000 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.400000 sec on serv conn 0:5cef812761a8eb78
0.384 log_pkt pkt.c:186 TX to=127.0.0.1:4987 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=5cef812761a8eb78 len=412 nr=3
enc_padding_frame frame.c:1099 PADDING len=98
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=1108 len=292 [RTX]
on_pkt_sent recovery.c:311 in_flight=1987 (+436), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.000000 (+0.000000), rttvar=0.000000 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.400000 sec on serv conn 0:5cef812761a8eb78
log_sent_pkts conn.c:229 epoch 0 unacked: *0 *1
log_sent_pkts conn.c:229 epoch 2 unacked: *0 *1 *2 *3
coalesce pkt.c:225 coalescing 0xfd len 436 behind 0xff len 299
0.447 log_pkt pkt.c:133 RX from=127.0.0.1:4987 len=109 0xfd=Handshake vers=0xff00000f dcid=5cef812761a8eb78 scid=000000000000000d len=101 nr=0
log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=52 [seq]
dec_ack_frame frame.c:391 ACK lg=1 delay=0 (0 usec) cnt=0 block=0 [1]
on_pkt_acked recovery.c:493 1 was RTX'ed as 3
detect_lost_pkts recovery.c:210 in_flight=1987 (+0), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.263230 (+0.263230), rttvar=0.131615 (+0.131615)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.463267 sec on serv conn 0:5cef812761a8eb78
dec_ack_frame frame.c:391 ACK lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
on_pkt_acked recovery.c:493 0 was RTX'ed as 2
detect_lost_pkts recovery.c:210 in_flight=1987 (+0), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.263230 (+0.000000), rttvar=0.098711 (-0.032904)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.463267 sec on serv conn 0:5cef812761a8eb78
dec_frames frame.c:895 PADDING len=15
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm -4 w/1 pkt in queue
log_sent_pkts conn.c:229 epoch 0 unacked: *0 *1
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm -2 w/2 pkts in queue
log_sent_pkts conn.c:229 epoch 0 unacked: *0 *1
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3
0.448 log_pkt pkt.c:194 TX to=127.0.0.1:4987 0x36=Short kyph=0 dcid=000000000000000d nr=0
enc_new_token_frame frame.c:1498 NEW_TOKEN len=40 tok=0573f52296eaf6a20abb89f62880f0674a6617cf6628ef6e8de788290051967b7f12d0477ff88495
enc_new_cid_frame frame.c:1477 NEW_CONNECTION_ID seq=1 len=8 cid=1:2c9c1fa3e6f0ae39 tok=62f607c548afa431a5388105b2b2fb40
on_pkt_sent recovery.c:311 in_flight=2082 (+95), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.263230 (+0.000000), rttvar=0.098711 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.463267 sec on serv conn 0:5cef812761a8eb78
0.472 ack_alarm pn.c:56 ACK timer fired on serv conn 0:5cef812761a8eb78 epoch 2
0.472 log_pkt pkt.c:186 TX to=127.0.0.1:4987 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=5cef812761a8eb78 len=0 nr=4
enc_ack_frame frame.c:1171 ACK lg=0 delay=3173 (25384 usec) cnt=0 block=0 [0]
0.905 log_pkt pkt.c:123 RX from=127.0.0.1:4987 len=1216 0xff=Initial vers=0xff00000f dcid=5cef812761a8eb78 scid=000000000000000d tok=7b len=1206 nr=2
dec_ack_frame frame.c:391 ACK lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
on_pkt_acked recovery.c:493 0 was RTX'ed as 1
detect_lost_pkts recovery.c:210 in_flight=2082 (+0), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.320503 (+0.057273), rttvar=0.188580 (+0.089868)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.119628 sec on serv conn 0:5cef812761a8eb78
dec_ack_frame frame.c:391 ACK lg=1 delay=0 (0 usec) cnt=0 block=0 [1]
on_pkt_acked recovery.c:506 stream -4 fully acked
detect_lost_pkts recovery.c:210 in_flight=1783 (-299), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.345613 (+0.025109), rttvar=0.191654 (+0.003074)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.169847 sec on serv conn 0:5cef812761a8eb78
dec_frames frame.c:895 PADDING len=1175
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm -2 w/2 pkts in queue
log_sent_pkts conn.c:229 epoch 1/3 unacked: 0
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3 (4)
1.075 on_ld_alarm recovery.c:226 crypto RTX #1 on serv conn 0:5cef812761a8eb78
detect_lost_pkts recovery.c:210 in_flight=1783 (+0), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.345613 (+0.000000), rttvar=0.191654 (+0.000000)
detect_lost_pkts recovery.c:210 in_flight=1783 (+0), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.345613 (+0.000000), rttvar=0.191654 (+0.000000)
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm -2 w/2 pkts in queue
log_sent_pkts conn.c:229 epoch 1/3 unacked: 0
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3 (4)
1.174 log_pkt pkt.c:141 RX from=127.0.0.1:4987 len=45 0x33=Short kyph=0 dcid=5cef812761a8eb78 nr=0
new_stream stream.c:101 serv conn 0:5cef812761a8eb78 strm 4 (bidir, clnt) state strm_idle -> strm_open
log_stream_or_crypto_frame frame.c:113 STREAM 0x16=LEN|OFF id=4/20 off=0/65535 len=7 coff=7/393210 [seq]
dec_ack_frame frame.c:391 ACK lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
detect_lost_pkts recovery.c:210 in_flight=1688 (-95), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.393355 (+0.047742), rttvar=0.239225 (+0.047571)
set_ld_timer recovery.c:129 ignoring crypto RTX alarm in -0.004035 sec on serv conn 0:5cef812761a8eb78
dec_frames frame.c:895 PADDING len=15
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm -2 w/2 pkts in queue
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3 (4)
1.175 log_pkt pkt.c:194 TX to=127.0.0.1:4987 0x34=Short kyph=0 dcid=000000000000000d nr=1
enc_ack_frame frame.c:1171 ACK lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
rx conn.c:1066 q_rx_ready(0, 0) done, exiting event loop
q_rx_ready quic.c:667 serv conn 0:5cef812761a8eb78 ready to rx
q_read quic.c:312 blocking read on serv conn 0:5cef812761a8eb78
q_read quic.c:335 read 7 bytes on serv conn 0:5cef812761a8eb78 strm 4
serve_cb server.c:110 conn 0:5cef812761a8eb78 str 4 serving URL /5
q_write quic.c:271 writing 5 bytes in 1 buf on serv conn 0:5cef812761a8eb78 strm 4
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm -2 w/2 pkts in queue
log_sent_pkts conn.c:229 epoch 1/3 unacked: (1)
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3 (4)
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm 4 w/1 pkt in queue
1.175 log_pkt pkt.c:194 TX to=127.0.0.1:4987 0x34=Short kyph=0 dcid=000000000000000d nr=2
enc_padding_frame frame.c:1099 PADDING len=38
log_stream_or_crypto_frame frame.c:113 STREAM 0x12=LEN id=4/20 off=0/8192 len=5 coff=0/16384
on_pkt_sent recovery.c:311 in_flight=1757 (+69), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.393355 (+0.000000), rttvar=0.239225 (+0.000000)
set_ld_timer recovery.c:129 ignoring crypto RTX alarm in -0.004719 sec on serv conn 0:5cef812761a8eb78
log_sent_pkts conn.c:229 epoch 1/3 unacked: (1) *2
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3 (4)
1.579 log_pkt pkt.c:133 RX from=127.0.0.1:4987 len=59 0xfd=Handshake vers=0xff00000f dcid=5cef812761a8eb78 scid=000000000000000d len=51 nr=2
dec_ack_frame frame.c:391 ACK lg=3 delay=0 (0 usec) cnt=0 block=0 [3]
detect_lost_pkts recovery.c:210 in_flight=1321 (-436), cwnd=6087 (+87), ssthresh=6000 (+0), srtt=0.493557 (+0.100202), rttvar=0.379823 (+0.140598)
set_ld_timer recovery.c:129 ignoring crypto RTX alarm in -0.207859 sec on serv conn 0:5cef812761a8eb78
dec_ack_frame frame.c:391 ACK lg=4 delay=0 (0 usec) cnt=0 block=0 [4]
detect_lost_pkts recovery.c:210 in_flight=1321 (+0), cwnd=6087 (+0), ssthresh=6000 (+0), srtt=0.570162 (+0.076604), rttvar=0.438076 (+0.058253)
set_ld_timer recovery.c:129 ignoring crypto RTX alarm in -0.054650 sec on serv conn 0:5cef812761a8eb78
dec_ack_frame frame.c:391 ACK lg=2 delay=0 (0 usec) cnt=0 block=0 [2]
on_pkt_acked recovery.c:506 stream -2 fully acked
detect_lost_pkts recovery.c:210 in_flight=69 (-1252), cwnd=6333 (+246), ssthresh=6000 (+0), srtt=0.648263 (+0.078102), rttvar=0.484760 (+0.046684)
set_ld_timer recovery.c:134 TLP alarm in 0.593850 sec on serv conn 0:5cef812761a8eb78
dec_frames frame.c:895 PADDING len=15
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm 4 w/1 pkt in queue
log_sent_pkts conn.c:229 epoch 1/3 unacked: (1) *2
1.829 log_pkt pkt.c:141 RX from=127.0.0.1:4987 len=34 0x30=Short kyph=0 dcid=5cef812761a8eb78 nr=4
dec_ack_frame frame.c:391 ACK lg=1 delay=0 (0 usec) cnt=0 block=0 [1]
detect_lost_pkts recovery.c:210 in_flight=69 (+0), cwnd=6333 (+0), ssthresh=6000 (+0), srtt=0.649110 (+0.000847), rttvar=0.365264 (-0.119496)
set_ld_timer recovery.c:134 TLP alarm in 0.344312 sec on serv conn 0:5cef812761a8eb78
dec_frames frame.c:895 PADDING len=15
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm 4 w/1 pkt in queue
log_sent_pkts conn.c:229 epoch 1/3 unacked: *2
2.174 on_ld_alarm recovery.c:239 TLP alarm #0 on serv conn 0:5cef812761a8eb78
2.174 log_pkt pkt.c:194 TX to=127.0.0.1:4987 0x35=Short kyph=0 dcid=000000000000000d nr=3
enc_padding_frame frame.c:1099 PADDING len=35
log_stream_or_crypto_frame frame.c:113 STREAM 0x12=LEN id=4/20 off=0/8192 len=5 coff=5/16384 [RTX]
on_pkt_sent recovery.c:311 in_flight=138 (+69), cwnd=6333 (+0), ssthresh=6000 (+0), srtt=0.649110 (+0.000000), rttvar=0.365264 (+0.000000)
set_ld_timer recovery.c:134 TLP alarm in 0.998665 sec on serv conn 0:5cef812761a8eb78
2.383 log_pkt pkt.c:141 RX from=127.0.0.1:4987 len=67 0x30=Short kyph=0 dcid=5cef812761a8eb78 nr=5
log_stream_or_crypto_frame frame.c:113 STREAM 0x16=LEN|OFF id=4/20 off=7/65535 len=8 coff=15/393210 [seq]
dec_ack_frame frame.c:391 ACK lg=2 delay=0 (0 usec) cnt=0 block=0 [2]
on_pkt_acked recovery.c:493 2 was RTX'ed as 3
detect_lost_pkts recovery.c:210 in_flight=69 (-69), cwnd=6346 (+13), ssthresh=6000 (+0), srtt=0.718918 (+0.069808), rttvar=0.413564 (+0.048300)
set_ld_timer recovery.c:134 TLP alarm in 0.895088 sec on serv conn 0:5cef812761a8eb78
dec_frames frame.c:907 addtl stream or crypto frame at pos 30, copy
log_stream_or_crypto_frame frame.c:113 STREAM 0x16=LEN|OFF id=4/20 off=15/65535 len=17 coff=32/393210 [seq]
dec_frames frame.c:895 PADDING len=15
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm 4 w/1 pkt in queue
log_sent_pkts conn.c:229 epoch 1/3 unacked: *3
2.383 log_pkt pkt.c:194 TX to=127.0.0.1:4987 0x30=Short kyph=0 dcid=000000000000000d nr=4
enc_ack_frame frame.c:1157 ACK lg=5 delay=0 (0 usec) cnt=0 block=1 [4..5]
2.683 log_pkt pkt.c:141 RX from=127.0.0.1:4987 len=34 0x30=Short kyph=0 dcid=5cef812761a8eb78 nr=7
dec_ack_frame frame.c:391 ACK lg=3 delay=0 (0 usec) cnt=0 block=0 [3]
on_pkt_acked recovery.c:506 stream 4 fully acked
on_pkt_acked recovery.c:509 q_write(c, s) done, exiting event loop
detect_lost_pkts recovery.c:210 in_flight=0 (-69), cwnd=6359 (+13), ssthresh=6000 (+0), srtt=0.692660 (-0.026258), rttvar=0.362690 (-0.050874)
dec_frames frame.c:895 PADDING len=15
q_write quic.c:293 wrote 5 bytes on serv conn 0:5cef812761a8eb78 strm 4
q_read quic.c:312 blocking read on serv conn 0:5cef812761a8eb78
q_read quic.c:335 read 25 bytes on serv conn 0:5cef812761a8eb78 strm 4
serve_cb server.c:110 conn 0:5cef812761a8eb78 str 4 serving URL /3
q_write quic.c:271 writing 3 bytes in 1 buf on serv conn 0:5cef812761a8eb78 strm 4
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm 4 w/1 pkt in queue
2.684 log_pkt pkt.c:194 TX to=127.0.0.1:4987 0x32=Short kyph=0 dcid=000000000000000d nr=5
enc_padding_frame frame.c:1099 PADDING len=38
log_stream_or_crypto_frame frame.c:113 STREAM 0x16=LEN|OFF id=4/20 off=5/8192 len=3 coff=5/16384
on_pkt_sent recovery.c:311 in_flight=67 (+67), cwnd=6359 (+0), ssthresh=6000 (+0), srtt=0.692660 (+0.000000), rttvar=0.362690 (+0.000000)
set_ld_timer recovery.c:134 TLP alarm in 1.063989 sec on serv conn 0:5cef812761a8eb78
log_sent_pkts conn.c:229 epoch 1/3 unacked: (4) *5
2.825 log_pkt pkt.c:141 RX from=127.0.0.1:4987 len=41 0x30=Short kyph=0 dcid=5cef812761a8eb78 nr=6
log_stream_or_crypto_frame frame.c:113 STREAM 0x16=LEN|OFF id=4/20 off=32/65535 len=8 coff=40/393210 [seq]
dec_frames frame.c:895 PADDING len=15
2.851 ack_alarm pn.c:56 ACK timer fired on serv conn 0:5cef812761a8eb78 epoch 3
2.851 log_pkt pkt.c:194 TX to=127.0.0.1:4987 0x32=Short kyph=0 dcid=000000000000000d nr=6
enc_ack_frame frame.c:1157 ACK lg=7 delay=3180 (25440 usec) cnt=0 block=3 [4..7]
3.419 rx_pkts conn.c:952 pkt came from new peer 127.0.0.1:4988, probing
3.419 log_pkt pkt.c:141 RX from=127.0.0.1:4988 len=51 0x30=Short kyph=0 dcid=5cef812761a8eb78 nr=2
dec_ack_frame frame.c:391 ACK lg=4 delay=0 (0 usec) cnt=0 block=0 [4]
detect_lost_pkts recovery.c:210 in_flight=67 (+0), cwnd=6359 (+0), ssthresh=6000 (+0), srtt=0.735579 (+0.042919), rttvar=0.357856 (-0.004834)
set_ld_timer recovery.c:134 TLP alarm in 0.393616 sec on serv conn 0:5cef812761a8eb78
dec_ack_frame frame.c:391 ACK lg=5 delay=0 (0 usec) cnt=0 block=0 [5]
on_pkt_acked recovery.c:506 stream 4 fully acked
on_pkt_acked recovery.c:509 q_write(c, s) done, exiting event loop
detect_lost_pkts recovery.c:210 in_flight=0 (-67), cwnd=6371 (+12), ssthresh=6000 (+0), srtt=0.735475 (-0.000103), rttvar=0.268598 (-0.089257)
log_stream_or_crypto_frame frame.c:113 STREAM 0x16=LEN|OFF id=4/20 off=40/65535 len=8 coff=48/393210 [seq]
dec_frames frame.c:895 PADDING len=15
3.419 log_pkt pkt.c:194 TX to=127.0.0.1:4988 0x31=Short kyph=0 dcid=000000000000000d nr=7
enc_ack_frame frame.c:1157 ACK lg=7 delay=74166 (593328 usec) cnt=1 block=1 [6..7]
enc_ack_frame frame.c:1164 ACK gap=2 block=0 [2]
enc_path_challenge_frame frame.c:1448 PATH_CHALLENGE data=9837de62dfc5febf
on_pkt_sent recovery.c:311 in_flight=45 (+45), cwnd=6371 (+0), ssthresh=6000 (+0), srtt=0.735475 (+0.000000), rttvar=0.268598 (+0.000000)
set_ld_timer recovery.c:134 TLP alarm in 1.128213 sec on serv conn 0:5cef812761a8eb78
q_write quic.c:293 wrote 3 bytes on serv conn 0:5cef812761a8eb78 strm 4
serve_cb server.c:110 conn 0:5cef812761a8eb78 str 4 serving URL /index.html
q_write quic.c:271 writing 4 bytes in 1 buf on serv conn 0:5cef812761a8eb78 strm 4
tx conn.c:429 data TX on serv conn 0:5cef812761a8eb78 strm 4 w/1 pkt in queue
3.420 log_pkt pkt.c:194 TX to=127.0.0.1:4988 0x32=Short kyph=0 dcid=000000000000000d nr=8
enc_path_challenge_frame frame.c:1448 PATH_CHALLENGE data=9837de62dfc5febf
enc_padding_frame frame.c:1099 PADDING len=29
log_stream_or_crypto_frame frame.c:113 STREAM 0x16=LEN|OFF id=4/20 off=8/8192 len=4 coff=8/16384
enc_path_challenge_frame frame.c:1448 PATH_CHALLENGE data=9837de62dfc5febf
on_pkt_sent recovery.c:311 in_flight=122 (+77), cwnd=6371 (+0), ssthresh=6000 (+0), srtt=0.735475 (+0.000000), rttvar=0.268598 (+0.000000)
set_ld_timer recovery.c:134 TLP alarm in 1.128213 sec on serv conn 0:5cef812761a8eb78
log_sent_pkts conn.c:229 epoch 1/3 unacked: (6) 7 *8
3.420 log_pkt pkt.c:194 TX to=127.0.0.1:4988 0x34=Short kyph=0 dcid=000000000000000d nr=9
enc_path_challenge_frame frame.c:1448 PATH_CHALLENGE data=9837de62dfc5febf
on_pkt_sent recovery.c:311 in_flight=157 (+35), cwnd=6371 (+0), ssthresh=6000 (+0), srtt=0.735475 (+0.000000), rttvar=0.268598 (+0.000000)
set_ld_timer recovery.c:134 TLP alarm in 1.128213 sec on serv conn 0:5cef812761a8eb78
from quant.
larseggert
commented on July 30, 2024
Thanks! I will look into this
from quant.
kenmcmil
commented on July 30, 2024
Just an update. This issue is still occurring in draft-17. Here's a case where the server sends a CLOSE_CONNECTION to a new port (4991) when the new port does not have a highest packet number. Notice that the first CONNECTION_CLOSE goes to the old address, then a packet comes in from the new address with a lower sequence number, and the server responds with CONNECTION_CLOSE to the new address.
There's no PATH_CHALLENGE, but I guess that makes sense, since the connection is in the closing state.
0.044 q_init quic.c:546 quant/socket 0.0.17/4ed3af4 with libev/epoll 4.22 ready
q_init quic.c:547 submit bug reports at https://github.com/NTAP/quant/issues
0.046 q_init quic.c:567 debug build, storing fuzzer corpus data
/home/mcmillan/projects/quant/lib/deps/warpcore/lib/src/ip.h:185:13: runtime error: member access within misaligned address 0x60400000031e for type 'struct ip_hdr', which requires 4 byte alignment
0x60400000031e: note: pointer points here
00 00 08 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
^
/home/mcmillan/projects/quant/lib/deps/warpcore/lib/src/ip.h:186:13: runtime error: member access within misaligned address 0x60400000031e for type 'struct ip_hdr', which requires 4 byte alignment
0x60400000031e: note: pointer points here
00 00 08 00 45 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
^
/home/mcmillan/projects/quant/lib/deps/warpcore/lib/src/ip.h:187:13: runtime error: member access within misaligned address 0x60400000031e for type 'struct ip_hdr', which requires 4 byte alignment
0x60400000031e: note: pointer points here
00 00 08 00 45 00 00 00 00 00 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
^
/home/mcmillan/projects/quant/lib/deps/warpcore/lib/src/ip.h:188:11: runtime error: member access within misaligned address 0x60400000031e for type 'struct ip_hdr', which requires 4 byte alignment
0x60400000031e: note: pointer points here
00 00 08 00 45 00 00 00 00 00 40 00 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
^
/home/mcmillan/projects/quant/lib/deps/warpcore/lib/src/ip.h:189:15: runtime error: member access within misaligned address 0x60400000031e for type 'struct ip_hdr', which requires 4 byte alignment
0x60400000031e: note: pointer points here
00 00 08 00 45 00 00 00 00 00 40 00 40 11 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
^
q_bind quic.c:393 bound serv socket on port 4443
main server.c:240 server waiting on lo port 4443
q_rx_ready quic.c:722 waiting for conn to get ready to rx
0.273 rx_pkts conn.c:938 new serv conn on port 4443 from 127.0.0.1:4992 w/cid=0:0000000000000005
new_conn conn.c:1437 serv conn 0:0000000000000005 on port 4443 created
new_conn conn.c:1439 serv conn 0:0000000000000005 state conn_clsd -> conn_idle
0.274 log_pkt pkt.c:98 RX from=127.0.0.1:4992 len=1216 0xc0=Initial vers=0xff000011 dcid=0000000000000005 scid=0000000000000004 tok= len=1207 nr=0
log_stream_or_crypto_frame frame.c:125 CRYPTO off=0 len=248 [seq]
dec_frames frame.c:957 PADDING len=937
rx_pkt conn.c:728 serv conn 0:0000000000000005 state conn_idle -> conn_opng
update_act_scid conn.c:491 hshk switch to scid 0:53ffc7df90032f58 for conn_opng serv conn (was 0:0000000000000005)
on_ch tls.c:304 SNI =
on_ch tls.c:329 ALPN = hq-17
chk_tp tls.c:502 initial_max_stream_data_bidi_local = 8192
chk_tp tls.c:514 initial_max_data = 16384
chk_tp tls.c:531 idle_timeout = 60
chk_tp tls.c:509 initial_max_stream_data_bidi_remote = 8192
chk_tp tls.c:496 initial_max_stream_data_uni = 8192
0.277 rx_crypto conn.c:590 serv conn 0:53ffc7df90032f58 state conn_opng -> conn_estb
tx_stream conn.c:349 TX on serv conn 0:53ffc7df90032f58 strm -4 w/1 pkt in queue
0.277 log_pkt pkt.c:148 TX to=127.0.0.1:4992 0xc0=Initial vers=0xff000011 dcid=0000000000000004 scid=53ffc7df90032f58 tok=dbb1e9ac7a773f032cfe8add81a4dcbb0b19fbd7a9e03c4b8519dcf49d3b282253ffc7df90032f58 len=0 nr=0
enc_ack_frame frame.c:1235 ACK 0x02= lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
enc_padding_frame frame.c:1161 PADDING len=17
log_stream_or_crypto_frame frame.c:125 CRYPTO off=0 len=155
on_pkt_sent recovery.c:295 in_flight=219 (+219), cwnd=12000 (+12000), ssthresh=0 (+0), srtt=0.000 (+0.000), rttvar=0.000 (+0.000)
set_ld_timer recovery.c:123 crypto RTX alarm in 0.200000 sec on serv conn 0:53ffc7df90032f58
log_sent_pkts conn.c:229 epoch 0 unacked: 0
tx_stream conn.c:349 TX on serv conn 0:53ffc7df90032f58 strm -2 w/2 pkts in queue
0.277 log_pkt pkt.c:157 TX to=127.0.0.1:4992 0xe0=Handshake vers=0xff000011 dcid=0000000000000004 scid=53ffc7df90032f58 len=0 nr=0
enc_padding_frame frame.c:1161 PADDING len=23
log_stream_or_crypto_frame frame.c:125 CRYPTO off=0 len=1188
on_pkt_sent recovery.c:295 in_flight=1471 (+1252), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.000 (+0.000), rttvar=0.000 (+0.000)
set_ld_timer recovery.c:123 crypto RTX alarm in 0.200000 sec on serv conn 0:53ffc7df90032f58
enc_pkt pkt.c:559 clnt path validated
0.277 log_pkt pkt.c:157 TX to=127.0.0.1:4992 0xe0=Handshake vers=0xff000011 dcid=0000000000000004 scid=53ffc7df90032f58 len=0 nr=1
enc_padding_frame frame.c:1161 PADDING len=23
log_stream_or_crypto_frame frame.c:125 CRYPTO off=1188 len=213
on_pkt_sent recovery.c:295 in_flight=1748 (+277), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.000 (+0.000), rttvar=0.000 (+0.000)
set_ld_timer recovery.c:123 crypto RTX alarm in 0.200000 sec on serv conn 0:53ffc7df90032f58
enc_pkt pkt.c:559 clnt path validated
log_sent_pkts conn.c:229 epoch 0 unacked: 0
log_sent_pkts conn.c:229 epoch 2 unacked: 0 1
coalesce pkt.c:195 coalescing 277-byte Handshake pkt behind 219-byte Initial pkt
0.461 log_pkt pkt.c:98 RX from=127.0.0.1:4992 len=1216 0xc0=Initial vers=0xff000011 dcid=53ffc7df90032f58 scid=0000000000000004 tok= len=1207 nr=2
dec_ack_frame frame.c:440 ACK 0x02= lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
dec_ack_frame frame.c:497 ECN verification failed for serv conn 0:53ffc7df90032f58
detect_lost_pkts recovery.c:207 in_flight=1529 (-219), cwnd=12219 (+219), ssthresh=0 (+0), srtt=0.188 (+0.188), rttvar=0.094 (+0.094)
set_ld_timer recovery.c:123 crypto RTX alarm in 0.187537 sec on serv conn 0:53ffc7df90032f58
dec_frames frame.c:957 PADDING len=1184
tx_stream conn.c:349 TX on serv conn 0:53ffc7df90032f58 strm -2 w/2 pkts in queue
log_sent_pkts conn.c:229 epoch 2 unacked: 0 1
0.584 abandon_pn pn.c:71 abandon serv epoch 0 processing
0.584 log_pkt pkt.c:107 RX from=127.0.0.1:4992 len=96 0xe0=Handshake vers=0xff000011 dcid=53ffc7df90032f58 scid=0000000000000004 len=88 nr=0
log_stream_or_crypto_frame frame.c:125 CRYPTO off=0 len=52 [seq]
dec_frames frame.c:957 PADDING len=15
tx_stream conn.c:349 TX on serv conn 0:53ffc7df90032f58 strm -2 w/2 pkts in queue
log_sent_pkts conn.c:229 epoch 2 unacked: 0 1
0.584 log_pkt pkt.c:157 TX to=127.0.0.1:4992 0xe0=Handshake vers=0xff000011 dcid=0000000000000004 scid=53ffc7df90032f58 len=0 nr=2
enc_ack_frame frame.c:1235 ACK 0x02= lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
0.649 on_ld_alarm recovery.c:223 crypto RTX #1 on serv conn 0:53ffc7df90032f58
detect_lost_pkts recovery.c:186 Handshake pkt 0 considered lost
detect_lost_pkts recovery.c:186 Handshake pkt 1 considered lost
detect_lost_pkts recovery.c:207 in_flight=0 (-1529), cwnd=12219 (+0), ssthresh=0 (+0), srtt=0.188 (+0.000), rttvar=0.094 (+0.000)
tx_stream conn.c:349 TX on serv conn 0:53ffc7df90032f58 strm -2 w/2 pkts in queue
0.649 log_pkt pkt.c:157 TX to=127.0.0.1:4992 0xe0=Handshake vers=0xff000011 dcid=0000000000000004 scid=53ffc7df90032f58 len=1228 nr=3
enc_padding_frame frame.c:1161 PADDING len=19
log_stream_or_crypto_frame frame.c:125 CRYPTO off=0 len=1188 [RTX]
on_pkt_sent recovery.c:295 in_flight=1252 (+1252), cwnd=12219 (+0), ssthresh=0 (+0), srtt=0.188 (+0.000), rttvar=0.094 (+0.000)
set_ld_timer recovery.c:123 crypto RTX alarm in 0.750147 sec on serv conn 0:53ffc7df90032f58
0.649 log_pkt pkt.c:157 TX to=127.0.0.1:4992 0xe0=Handshake vers=0xff000011 dcid=0000000000000004 scid=53ffc7df90032f58 len=253 nr=4
enc_padding_frame frame.c:1161 PADDING len=18
log_stream_or_crypto_frame frame.c:125 CRYPTO off=1188 len=213 [RTX]
on_pkt_sent recovery.c:295 in_flight=1529 (+277), cwnd=12219 (+0), ssthresh=0 (+0), srtt=0.188 (+0.000), rttvar=0.094 (+0.000)
set_ld_timer recovery.c:123 crypto RTX alarm in 0.750147 sec on serv conn 0:53ffc7df90032f58
log_sent_pkts conn.c:229 epoch 2 unacked: 0 1 3 4
0.729 log_pkt pkt.c:107 RX from=127.0.0.1:4992 len=46 0xe0=Handshake vers=0xff000011 dcid=53ffc7df90032f58 scid=0000000000000004 len=38 nr=8
dec_ack_frame frame.c:440 ACK 0x02= lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
on_pkt_acked recovery.c:402 0 was RTX'ed as 3
detect_lost_pkts recovery.c:207 in_flight=1529 (+0), cwnd=12219 (+0), ssthresh=0 (+0), srtt=0.221 (+0.034), rttvar=0.137 (+0.044)
set_ld_timer recovery.c:123 crypto RTX alarm in 0.361927 sec on serv conn 0:53ffc7df90032f58
dec_frames frame.c:957 PADDING len=15
tx_stream conn.c:349 TX on serv conn 0:53ffc7df90032f58 strm -2 w/2 pkts in queue
log_sent_pkts conn.c:229 epoch 2 unacked: 1 3 4
0.936 log_pkt pkt.c:116 RX from=127.0.0.1:4992 len=1216 0x40=Short kyph=0 spin=0 dcid=53ffc7df90032f58 nr=0
dec_stop_sending_frame frame.c:758 STOP_SENDING id=4 err=0xf90c
err_close conn.c:1184 unknown strm 4
enter_closing conn.c:1252 closing/draining alarm in 1.212669 sec on serv conn 0:53ffc7df90032f58
enter_closing conn.c:1258 serv conn 0:53ffc7df90032f58 state conn_estb -> conn_clsg
1.171 log_pkt pkt.c:107 RX from=127.0.0.1:4992 len=46 0xe0=Handshake vers=0xff000011 dcid=53ffc7df90032f58 scid=0000000000000004 len=38 nr=14
dec_ack_frame frame.c:440 ACK 0x02= lg=3 delay=0 (0 usec) cnt=0 block=0 [3]
detect_lost_pkts recovery.c:207 in_flight=277 (-1252), cwnd=13471 (+1252), ssthresh=0 (+0), srtt=0.259 (+0.038), rttvar=0.178 (+0.041)
dec_frames frame.c:957 PADDING len=15
1.439 log_pkt pkt.c:116 RX from=127.0.0.1:4992 len=1216 0x40=Short kyph=0 spin=0 dcid=53ffc7df90032f58 nr=15
new_stream stream.c:103 serv conn 0:53ffc7df90032f58 strm 4 (bi, clnt) state strm_idle -> strm_open
dec_stream_or_crypto_frame frame.c:292 serv conn 0:53ffc7df90032f58 strm 4 (bi, clnt) state strm_open -> strm_hcrm
log_stream_or_crypto_frame frame.c:120 STREAM 0x0f=FIN|LEN|OFF id=4/20 off=0/65535 len=6 coff=6/393210 [seq]
dec_frames frame.c:968 addtl stream or crypto frame at pos 20, copy
new_stream stream.c:103 serv conn 0:53ffc7df90032f58 strm 16 (bi, clnt) state strm_idle -> strm_open
dec_stream_or_crypto_frame frame.c:292 serv conn 0:53ffc7df90032f58 strm 16 (bi, clnt) state strm_open -> strm_hcrm
log_stream_or_crypto_frame frame.c:120 STREAM 0x0f=FIN|LEN|OFF id=16/20 off=0/65535 len=6 coff=12/393210 [seq]
dec_frames frame.c:957 PADDING len=1185
rx conn.c:1154 q_rx_ready(0, 0) done, exiting event loop
q_rx_ready quic.c:730 serv conn 0:53ffc7df90032f58 ready to rx
q_accept quic.c:441 serv conn 0:53ffc7df90032f58 accepted from clnt 127.0.0.1:4992, cipher AES256-GCM
q_read quic.c:337 non-blocking read on serv conn 0:53ffc7df90032f58
q_read quic.c:362 read 0 bytes on serv conn 0:53ffc7df90032f58 strm -1
q_close quic.c:609 closing serv conn 0:53ffc7df90032f58 on port 4443
q_close quic.c:617 serv conn 0:53ffc7df90032f58 state conn_clsg -> conn_qlse
enter_closing conn.c:1258 serv conn 0:53ffc7df90032f58 state conn_qlse -> conn_clsg
1.439 log_pkt pkt.c:166 TX to=127.0.0.1:4992 0x40=Short kyph=0 spin=0 dcid=0000000000000004 nr=0
enc_ack_frame frame.c:1235 ACK 0x02= lg=15 delay=116 (928 usec) cnt=1 block=0 [15]
enc_ack_frame frame.c:1226 ACK gap=13 block=0 [0]
enc_close_frame frame.c:1339 CONNECTION_CLOSE 0x1c=quic err=0x000a frame=0x05 rlen=15 reason=unknown strm 4
on_pkt_sent recovery.c:295 in_flight=331 (+54), cwnd=13471 (+0), ssthresh=0 (+0), srtt=0.259 (+0.000), rttvar=0.178 (+0.000)
1.655 rx_pkts conn.c:987 pkt came from new peer 127.0.0.1:4991, probing
1.655 log_pkt pkt.c:116 RX from=127.0.0.1:4991 len=1216 0x40=Short kyph=0 spin=0 dcid=53ffc7df90032f58 nr=9
new_stream stream.c:103 serv conn 0:53ffc7df90032f58 strm 12 (bi, clnt) state strm_idle -> strm_open
dec_stream_or_crypto_frame frame.c:292 serv conn 0:53ffc7df90032f58 strm 12 (bi, clnt) state strm_open -> strm_hcrm
log_stream_or_crypto_frame frame.c:120 STREAM 0x0f=FIN|LEN|OFF id=12/20 off=0/65535 len=6 coff=18/393210 [seq]
dec_frames frame.c:957 PADDING len=1195
1.680 ack_alarm conn.c:1282 ACK timer fired on serv conn 0:53ffc7df90032f58
1.680 log_pkt pkt.c:166 TX to=127.0.0.1:4991 0x40=Short kyph=0 spin=0 dcid=0000000000000004 nr=1
enc_ack_frame frame.c:1235 ACK 0x02= lg=15 delay=30240 (241920 usec) cnt=2 block=0 [15]
enc_ack_frame frame.c:1226 ACK gap=4 block=0 [9]
enc_ack_frame frame.c:1226 ACK gap=7 block=0 [0]
enc_close_frame frame.c:1339 CONNECTION_CLOSE 0x1c=quic err=0x000a frame=0x05 rlen=15 reason=unknown strm 4
on_pkt_sent recovery.c:295 in_flight=389 (+58), cwnd=13471 (+0), ssthresh=0 (+0), srtt=0.259 (+0.000), rttvar=0.178 (+0.000)
1.966 log_pkt pkt.c:116 RX from=127.0.0.1:4991 len=1216 0x40=Short kyph=0 spin=0 dcid=53ffc7df90032f58 nr=4
dec_stop_sending_frame frame.c:758 STOP_SENDING id=4 err=0xe8e5
dec_ack_frame frame.c:440 ACK 0x02= lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
dec_frames frame.c:957 PADDING len=1196
from quant.
larseggert
commented on July 30, 2024
quant is on -18 now, and I made some changes to that codepath. I don't think they fix this yet, but maybe you could re-run, or tell me how to?
from quant.
kenmcmil
commented on July 30, 2024
This issue is still occurring as of commit b50abb9. A log follows, showing a case where a connection is initiated by client port 4991, then a packet is received from port 4992 at 1.381 with a non-highest packet number (8, when the highest is 13). The server sends a PATH_CHALLENGE to 4992.
You may be able to repro this with this docker container: kenmcmil/quictest:v0.9
The symptom is:
quic_connection.ivy: line 686: error: assumption failed
This happened on the third run in my tests.
0.034 q_init quic.c:583 quant/socket 0.0.18/b50abb9 with libev/epoll 4.22 ready
q_init quic.c:584 submit bug reports at https://github.com/NTAP/quant/issues
0.036 q_init quic.c:603 debug build, storing fuzzer corpus data
q_bind quic.c:426 bound serv socket to port 4443
main server.c:265 server waiting on lo port 4443
q_rx_ready quic.c:778 waiting for conn to get ready to rx
0.233 rx_pkts conn.c:1036 new serv conn on port 4443 from 127.0.0.1:4991 w/cid=0:0000000000000005
new_conn conn.c:1571 serv conn 0:0000000000000005 on port 4443 created
new_conn conn.c:1573 serv conn 0:0000000000000005 state conn_clsd -> conn_idle
0.233 log_pkt pkt.c:103 RX from=127.0.0.1:4991 len=1216 0xc0=Initial vers=0xff000012 dcid=0000000000000005 scid=0000000000000004 tok= len=1207 nr=0
log_stream_or_crypto_frame frame.c:134 CRYPTO off=0 len=267 [seq]
dec_frames frame.c:1024 PADDING len=918
rx_pkt conn.c:808 serv conn 0:0000000000000005 state conn_idle -> conn_opng
update_act_scid conn.c:570 hshk switch to scid 0:5fd9d9eab1507c05 for conn_opng serv conn (was 0:0000000000000005)
on_ch tls.c:291 SNI = servername
on_ch tls.c:314 ALPN = hq-17 (and maybe others, none supported, ignoring)
chk_tp tls.c:494 initial_max_stream_data_bidi_local = 8192
chk_tp tls.c:506 initial_max_data = 16384
chk_tp tls.c:523 idle_timeout = 60
chk_tp tls.c:501 initial_max_stream_data_bidi_remote = 8192
chk_tp tls.c:488 initial_max_stream_data_uni = 8192
0.236 rx_crypto conn.c:677 serv conn 0:5fd9d9eab1507c05 state conn_opng -> conn_estb
0.236 log_pkt pkt.c:153 TX to=127.0.0.1:4991 0xc0=Initial vers=0xff000012 dcid=0000000000000004 scid=5fd9d9eab1507c05 tok=e1216eb26c3c50ff588dc890c3d009dfa8524429f59dce56f22aaca2505467095fd9d9eab1507c05 len=0 nr=0
enc_ack_frame frame.c:1302 ACK 0x02= lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
enc_padding_frame frame.c:1228 PADDING len=17
log_stream_or_crypto_frame frame.c:134 CRYPTO off=0 len=155
on_pkt_sent recovery.c:321 in_flight=219 (+219), cwnd=12000 (+12000), ssthresh=0 (+0), srtt=0.000 (+0.000), rttvar=0.000 (+0.000)
0.236 log_pkt pkt.c:162 TX to=127.0.0.1:4991 0xe0=Handshake vers=0xff000012 dcid=0000000000000004 scid=5fd9d9eab1507c05 len=0 nr=0
enc_padding_frame frame.c:1228 PADDING len=23
log_stream_or_crypto_frame frame.c:134 CRYPTO off=0 len=1188
on_pkt_sent recovery.c:321 in_flight=1471 (+1252), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.000 (+0.000), rttvar=0.000 (+0.000)
0.236 log_pkt pkt.c:162 TX to=127.0.0.1:4991 0xe0=Handshake vers=0xff000012 dcid=0000000000000004 scid=5fd9d9eab1507c05 len=0 nr=1
enc_padding_frame frame.c:1228 PADDING len=23
log_stream_or_crypto_frame frame.c:134 CRYPTO off=1188 len=205
on_pkt_sent recovery.c:321 in_flight=1740 (+269), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.000 (+0.000), rttvar=0.000 (+0.000)
coalesce pkt.c:200 coalescing 269-byte Handshake pkt behind 219-byte Initial pkt
log_sent_pkts conn.c:260 serv epoch 0 unacked: 0
log_sent_pkts conn.c:260 serv epoch 2 unacked: 0 1
0.405 log_pkt pkt.c:103 RX from=127.0.0.1:4991 len=1216 0xc0=Initial vers=0xff000012 dcid=5fd9d9eab1507c05 scid=0000000000000004 tok= len=1207 nr=16
dec_ack_frame frame.c:473 ACK 0x02= lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
dec_ack_frame frame.c:533 ECN verification failed for serv conn 0:5fd9d9eab1507c05
detect_lost_pkts recovery.c:230 in_flight=1521 (-219), cwnd=12219 (+219), ssthresh=0 (+0), srtt=0.172 (+0.172), rttvar=0.086 (+0.086)
has_pval_wnd conn.h:439 serv conn 0:5fd9d9eab1507c05 path val lim reached: 1740 + 2020 >= 3696
dec_frames frame.c:1024 PADDING len=1184
0.509 abandon_pn pn.c:122 abandon serv epoch 0 processing
dec_pkt_hdr_remainder pkt.c:898 clnt path validated
0.509 log_pkt pkt.c:112 RX from=127.0.0.1:4991 len=96 0xe0=Handshake vers=0xff000012 dcid=5fd9d9eab1507c05 scid=0000000000000004 len=88 nr=0
log_stream_or_crypto_frame frame.c:134 CRYPTO off=0 len=52 [seq]
dec_frames frame.c:1024 PADDING len=15
0.510 log_pkt pkt.c:162 TX to=127.0.0.1:4991 0xe0=Handshake vers=0xff000012 dcid=0000000000000004 scid=5fd9d9eab1507c05 len=0 nr=2
enc_ack_frame frame.c:1302 ACK 0x02= lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
log_sent_pkts conn.c:260 serv epoch 2 unacked: 0 1 2
0.578 on_ld_alarm recovery.c:246 crypto RTX #1 on serv conn 0:5fd9d9eab1507c05
detect_lost_pkts recovery.c:225 serv Handshake pkt 0 considered lost
detect_lost_pkts recovery.c:225 serv Handshake pkt 1 considered lost
detect_lost_pkts recovery.c:230 in_flight=0 (-1521), cwnd=12219 (+0), ssthresh=0 (+0), srtt=0.172 (+0.000), rttvar=0.086 (+0.000)
0.578 log_pkt pkt.c:162 TX to=127.0.0.1:4991 0xe0=Handshake vers=0xff000012 dcid=0000000000000004 scid=5fd9d9eab1507c05 len=1228 nr=3
enc_padding_frame frame.c:1228 PADDING len=19
log_stream_or_crypto_frame frame.c:134 CRYPTO off=0 len=1188 [RTX]
on_pkt_sent recovery.c:321 in_flight=1252 (+1252), cwnd=12219 (+0), ssthresh=0 (+0), srtt=0.172 (+0.000), rttvar=0.086 (+0.000)
0.578 log_pkt pkt.c:162 TX to=127.0.0.1:4991 0xe0=Handshake vers=0xff000012 dcid=0000000000000004 scid=5fd9d9eab1507c05 len=245 nr=4
enc_padding_frame frame.c:1228 PADDING len=18
log_stream_or_crypto_frame frame.c:134 CRYPTO off=1188 len=205 [RTX]
on_pkt_sent recovery.c:321 in_flight=1521 (+269), cwnd=12219 (+0), ssthresh=0 (+0), srtt=0.172 (+0.000), rttvar=0.086 (+0.000)
log_sent_pkts conn.c:260 serv epoch 2 unacked: 4 2 3
0.717 log_pkt pkt.c:121 RX from=127.0.0.1:4991 len=1216 0x40=Short kyph=0 spin=0 dcid=5fd9d9eab1507c05 nr=0
new_stream stream.c:104 serv conn 0:5fd9d9eab1507c05 strm 8 (bi, clnt) state strm_idle -> strm_open
dec_stream_or_crypto_frame frame.c:320 serv conn 0:5fd9d9eab1507c05 strm 8 (bi, clnt) state strm_open -> strm_hcrm
log_stream_or_crypto_frame frame.c:129 STREAM 0x0f=FIN|LEN|OFF id=8/20 off=0/65535 len=16 coff=16/393210 [seq]
dec_stop_sending_frame frame.c:803 STOP_SENDING id=4 err=0xd57a
new_stream stream.c:104 serv conn 0:5fd9d9eab1507c05 strm 4 (bi, clnt) state strm_idle -> strm_open
dec_stop_sending_frame frame.c:803 STOP_SENDING id=4 err=0x2308
dec_frames frame.c:1024 PADDING len=1177
rx conn.c:1281 q_rx_ready(0, 0) done, exiting event loop
q_rx_ready quic.c:786 serv conn 0:5fd9d9eab1507c05 ready to rx
q_accept quic.c:480 serv conn 0:5fd9d9eab1507c05 accepted from clnt 127.0.0.1:4991, cipher AES256-GCM
q_read quic.c:336 non-blocking read on serv conn 0:5fd9d9eab1507c05
q_read quic.c:376 read 16 bytes in 0.000 sec (113.475 Mb/s) on serv conn 0:5fd9d9eab1507c05 strm 8
serve_cb server.c:127 conn 0:5fd9d9eab1507c05 str 8 serving URL /index.html
q_write quic.c:265 writing 4 bytes in 1 buf on serv conn 0:5fd9d9eab1507c05 strm 8 and closing
0.717 log_pkt pkt.c:171 TX to=127.0.0.1:4991 0x40=Short kyph=0 spin=0 dcid=0000000000000004 nr=0
enc_ack_frame frame.c:1302 ACK 0x02= lg=0 delay=98 (784 usec) cnt=0 block=0 [0]
enc_padding_frame frame.c:1228 PADDING len=32
log_stream_or_crypto_frame frame.c:129 STREAM 0x0b=FIN|LEN id=8/20 off=0/8192 len=4 coff=0/16384
enc_new_token_frame frame.c:1619 NEW_TOKEN len=40 tok=e1216eb26c3c50ff588dc890c3d009dfa8524429f59dce56f22aaca2505467095fd9d9eab1507c05
enc_new_cid_frame frame.c:1598 NEW_CONNECTION_ID seq=1 len=8 cid=1:a9ceeb1d0deb47a3 srt=6dc8abbac43f7965f7696a59c7337c6b
on_pkt_sent recovery.c:321 in_flight=1658 (+137), cwnd=12219 (+0), ssthresh=0 (+0), srtt=0.172 (+0.000), rttvar=0.086 (+0.000)
log_sent_pkts conn.c:260 serv epoch 1/3 unacked: 0
log_sent_pkts conn.c:260 serv epoch 2 unacked: 4 2 3
0.854 log_pkt pkt.c:121 RX from=127.0.0.1:4991 len=1216 0x40=Short kyph=0 spin=0 dcid=5fd9d9eab1507c05 nr=12
new_stream stream.c:104 serv conn 0:5fd9d9eab1507c05 strm 12 (bi, clnt) state strm_idle -> strm_open
dec_stream_or_crypto_frame frame.c:320 serv conn 0:5fd9d9eab1507c05 strm 12 (bi, clnt) state strm_open -> strm_hcrm
log_stream_or_crypto_frame frame.c:129 STREAM 0x0f=FIN|LEN|OFF id=12/20 off=0/65535 len=16 coff=32/393210 [seq]
dec_frames frame.c:1024 PADDING len=1185
0.879 ack_alarm conn.c:1409 ACK timer fired on serv conn 0:5fd9d9eab1507c05
0.879 log_pkt pkt.c:171 TX to=127.0.0.1:4991 0x40=Short kyph=0 spin=0 dcid=0000000000000004 nr=1
enc_ack_frame frame.c:1302 ACK 0x02= lg=12 delay=3181 (25448 usec) cnt=1 block=0 [12]
enc_ack_frame frame.c:1293 ACK gap=10 block=0 [0]
log_sent_pkts conn.c:260 serv epoch 1/3 unacked: 0 1
log_sent_pkts conn.c:260 serv epoch 2 unacked: 4 2 3
1.026 log_pkt pkt.c:121 RX from=127.0.0.1:4991 len=1216 0x40=Short kyph=0 spin=0 dcid=5fd9d9eab1507c05 nr=13
dec_ack_frame frame.c:473 ACK 0x02= lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
on_pkt_acked recovery.c:451 q_write(c, s) done, exiting event loop
detect_lost_pkts recovery.c:230 in_flight=1521 (-137), cwnd=12356 (+137), ssthresh=0 (+0), srtt=0.189 (+0.017), rttvar=0.099 (+0.013)
on_ld_alarm recovery.c:246 crypto RTX #1 on serv conn 0:5fd9d9eab1507c05
detect_lost_pkts recovery.c:225 serv Handshake pkt 4 considered lost
detect_lost_pkts recovery.c:225 serv Handshake pkt 2 considered lost
detect_lost_pkts recovery.c:225 serv Handshake pkt 3 considered lost
detect_lost_pkts recovery.c:230 in_flight=0 (-1521), cwnd=12356 (+0), ssthresh=0 (+0), srtt=0.189 (+0.000), rttvar=0.099 (+0.000)
1.026 log_pkt pkt.c:162 TX to=127.0.0.1:4991 0xe0=Handshake vers=0xff000012 dcid=0000000000000004 scid=5fd9d9eab1507c05 len=1228 nr=5
enc_padding_frame frame.c:1228 PADDING len=19
log_stream_or_crypto_frame frame.c:134 CRYPTO off=0 len=1188 [RTX]
on_pkt_sent recovery.c:321 in_flight=1252 (+1252), cwnd=12356 (+0), ssthresh=0 (+0), srtt=0.189 (+0.000), rttvar=0.099 (+0.000)
1.026 log_pkt pkt.c:162 TX to=127.0.0.1:4991 0xe0=Handshake vers=0xff000012 dcid=0000000000000004 scid=5fd9d9eab1507c05 len=245 nr=6
enc_padding_frame frame.c:1228 PADDING len=18
log_stream_or_crypto_frame frame.c:134 CRYPTO off=1188 len=205 [RTX]
on_pkt_sent recovery.c:321 in_flight=1521 (+269), cwnd=12356 (+0), ssthresh=0 (+0), srtt=0.189 (+0.000), rttvar=0.099 (+0.000)
log_sent_pkts conn.c:260 serv epoch 1/3 unacked: 1
log_sent_pkts conn.c:260 serv epoch 2 unacked: 5 6
dec_frames frame.c:1024 PADDING len=1200
q_write quic.c:308 serv conn 0:5fd9d9eab1507c05 strm 8 (bi, clnt) state strm_hcrm -> strm_clsd
q_write quic.c:315 wrote 4 bytes in 0.309 sec (103.455 b/s) on serv conn 0:5fd9d9eab1507c05 strm 8 and closed
free_stream stream.c:145 freeing strm 8 on serv conn 0:5fd9d9eab1507c05
q_read quic.c:336 non-blocking read on serv conn 0:5fd9d9eab1507c05
q_read quic.c:376 read 16 bytes in 0.000 sec (179.021 Mb/s) on serv conn 0:5fd9d9eab1507c05 strm 12
serve_cb server.c:127 conn 0:5fd9d9eab1507c05 str 12 serving URL /index.html
q_write quic.c:265 writing 4 bytes in 1 buf on serv conn 0:5fd9d9eab1507c05 strm 12 and closing
1.027 log_pkt pkt.c:171 TX to=127.0.0.1:4991 0x40=Short kyph=0 spin=0 dcid=0000000000000004 nr=2
enc_ack_frame frame.c:1286 ACK 0x02= lg=13 delay=108 (864 usec) cnt=0 block=1 [12..3]
enc_padding_frame frame.c:1228 PADDING len=32
log_stream_or_crypto_frame frame.c:129 STREAM 0x0b=FIN|LEN id=12/20 off=0/8192 len=4 coff=4/16384
on_pkt_sent recovery.c:321 in_flight=1589 (+68), cwnd=12356 (+0), ssthresh=0 (+0), srtt=0.189 (+0.000), rttvar=0.099 (+0.000)
log_sent_pkts conn.c:260 serv epoch 1/3 unacked: 1 2
log_sent_pkts conn.c:260 serv epoch 2 unacked: 5 6
1.380 rx_pkts conn.c:1098 pkt came from new peer 127.0.0.1:4992, probing
1.381 log_pkt pkt.c:121 RX from=127.0.0.1:4992 len=1216 0x40=Short kyph=0 spin=0 dcid=5fd9d9eab1507c05 nr=8
dec_stop_sending_frame frame.c:803 STOP_SENDING id=4 err=0x4368
dec_ack_frame frame.c:473 ACK 0x02= lg=1 delay=0 (0 usec) cnt=0 block=0 [1]
detect_lost_pkts recovery.c:225 serv Short pkt 2 considered lost
detect_lost_pkts recovery.c:230 in_flight=1521 (-68), cwnd=6178 (-6178), ssthresh=6178 (+6178), srtt=0.189 (+0.000), rttvar=0.099 (+0.000)
1.381 log_pkt pkt.c:171 TX to=127.0.0.1:4992 0x40=Short kyph=0 spin=0 dcid=0000000000000004 nr=3
enc_path_challenge_frame frame.c:1570 PATH_CHALLENGE data=1964376cc8a6f52c
enc_padding_frame frame.c:1228 PADDING len=26
log_stream_or_crypto_frame frame.c:129 STREAM 0x0b=FIN|LEN id=12/20 off=0/8192 len=4 coff=8/16384 [RTX]
on_pkt_sent recovery.c:321 in_flight=1589 (+68), cwnd=6178 (+0), ssthresh=6178 (+0), srtt=0.189 (+0.000), rttvar=0.099 (+0.000)
log_sent_pkts conn.c:260 serv epoch 1/3 unacked: 3
log_sent_pkts conn.c:260 serv epoch 2 unacked: 5 6
dec_stream_or_crypto_frame frame.c:320 serv conn 0:5fd9d9eab1507c05 strm 4 (bi, clnt) state strm_open -> strm_hcrm
log_stream_or_crypto_frame frame.c:129 STREAM 0x0f=FIN|LEN|OFF id=4/20 off=0/65535 len=16 coff=48/393210 [seq]
dec_stop_sending_frame frame.c:803 STOP_SENDING id=4 err=0xd178
dec_stop_sending_frame frame.c:803 STOP_SENDING id=4 err=0xe2a1
dec_frames frame.c:1024 PADDING len=1168
1.405 on_ld_alarm recovery.c:246 crypto RTX #1 on serv conn 0:5fd9d9eab1507c05
detect_lost_pkts recovery.c:225 serv Handshake pkt 5 considered lost
detect_lost_pkts recovery.c:225 serv Handshake pkt 6 considered lost
detect_lost_pkts recovery.c:230 in_flight=68 (-1521), cwnd=6178 (+0), ssthresh=6178 (+0), srtt=0.189 (+0.000), rttvar=0.099 (+0.000)
1.405 log_pkt pkt.c:162 TX to=127.0.0.1:4992 0xe0=Handshake vers=0xff000012 dcid=0000000000000004 scid=5fd9d9eab1507c05 len=1228 nr=7
enc_padding_frame frame.c:1228 PADDING len=19
log_stream_or_crypto_frame frame.c:134 CRYPTO off=0 len=1188 [RTX]
on_pkt_sent recovery.c:321 in_flight=1320 (+1252), cwnd=6178 (+0), ssthresh=6178 (+0), srtt=0.189 (+0.000), rttvar=0.099 (+0.000)
1.405 log_pkt pkt.c:162 TX to=127.0.0.1:4992 0xe0=Handshake vers=0xff000012 dcid=0000000000000004 scid=5fd9d9eab1507c05 len=245 nr=8
enc_padding_frame frame.c:1228 PADDING len=18
log_stream_or_crypto_frame frame.c:134 CRYPTO off=1188 len=205 [RTX]
on_pkt_sent recovery.c:321 in_flight=1589 (+269), cwnd=6178 (+0), ssthresh=6178 (+0), srtt=0.189 (+0.000), rttvar=0.099 (+0.000)
log_sent_pkts conn.c:260 serv epoch 1/3 unacked: 3
log_sent_pkts conn.c:260 serv epoch 2 unacked: 8 7
1.406 ack_alarm conn.c:1409 ACK timer fired on serv conn 0:5fd9d9eab1507c05
1.407 log_pkt pkt.c:171 TX to=127.0.0.1:4992 0x40=Short kyph=0 spin=0 dcid=0000000000000004 nr=4
enc_ack_frame frame.c:1302 ACK 0x02= lg=13 delay=47575 (380600 usec) cnt=1 block=0 [13]
enc_ack_frame frame.c:1293 ACK gap=3 block=0 [8]
enc_path_challenge_frame frame.c:1570 PATH_CHALLENGE data=1964376cc8a6f52c
on_pkt_sent recovery.c:321 in_flight=1634 (+45), cwnd=6178 (+0), ssthresh=6178 (+0), srtt=0.189 (+0.000), rttvar=0.099 (+0.000)
log_sent_pkts conn.c:260 serv epoch 1/3 unacked: 4 3
log_sent_pkts conn.c:260 serv epoch 2 unacked: 8 7
1.523 log_pkt pkt.c:121 RX from=127.0.0.1:4991 len=1216 0x40=Short kyph=0 spin=0 dcid=5fd9d9eab1507c05 nr=1
dec_stop_sending_frame frame.c:803 STOP_SENDING id=4 err=0x4661
dec_frames frame.c:1024 PADDING len=1201
1.548 ack_alarm conn.c:1409 ACK timer fired on serv conn 0:5fd9d9eab1507c05
1.548 log_pkt pkt.c:171 TX to=127.0.0.1:4992 0x40=Short kyph=0 spin=0 dcid=0000000000000004 nr=5
enc_ack_frame frame.c:1302 ACK 0x02= lg=13 delay=65304 (522432 usec) cnt=2 block=0 [13]
enc_ack_frame frame.c:1293 ACK gap=3 block=0 [8]
enc_ack_frame frame.c:1293 ACK gap=5 block=0 [1]
enc_path_challenge_frame frame.c:1570 PATH_CHALLENGE data=1964376cc8a6f52c
on_pkt_sent recovery.c:321 in_flight=1681 (+47), cwnd=6178 (+0), ssthresh=6178 (+0), srtt=0.189 (+0.000), rttvar=0.099 (+0.000)
log_sent_pkts conn.c:260 serv epoch 1/3 unacked: 4 5 3
log_sent_pkts conn.c:260 serv epoch 2 unacked: 8 7
from quant.
larseggert
commented on July 30, 2024
Thanks! I will try to reproduce this locally.
from quant.
larseggert
commented on July 30, 2024
This should be fixed in e9fc651
from quant.
Related Issues (20)
- DoS Attack: Server crashes when processing new connections ids that have the same cid HOT 7
- TLS ticket read error HOT 4
- Failed to build on Ubuntu HOT 19
- Support for QUIC datagrams HOT 2
- Decryption of QUIC packets using secret keys with wireshark HOT 1
- Basic setup of server and client configuration HOT 4
- Some installation issues on Ubuntu 16, 20 and MacOSX HOT 1
- failed to run ./server or ./server-warp HOT 24
- krng.h runtime error on mac osx HOT 2
- Retiring the initial connection ID HOT 9
- fc window exceeded HOT 2
- Release/server HOT 2
- reference paper HOT 1
- Problems with Ninja and server.c in /bin HOT 12
- Quant server misbehaves when a ping is sent as the first Initial packet. HOT 1
- Fail to build on m1 osx HOT 2
- Failed to compile bench_conn and bench HOT 4
- bench_conn core dump HOT 2
- Protocol Violation in Quant HOT 1
- Quant server process Handshake packet with an unmatched Destination Connection ID. HOT 4
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 quant.