Comments (6)
larseggert
commented on July 30, 2024
I have seen this before, too, but I can't reproduce it, and it happens so rarely that I haven't prioritized looking into it. I am committing some extra instrumentation so that if it does happen again, I might get a hint towards what is causing it.
from quant.
kenmcmil
commented on July 30, 2024
Here's a log that seems to be of ta similar problem, but it produces a different message in a different function.
0.035 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.037 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.165 rx_pkts conn.c:918 new serv conn on port 4443 from 127.0.0.1:4988 w/cid=0:000000000000000b
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:000000000000000b on port 4443 created
new_conn conn.c:1313 serv conn 0:000000000000000b state conn_clsd -> conn_idle
0.166 log_pkt pkt.c:123 RX from=127.0.0.1:4988 len=1216 0xff=Initial vers=0xff00000f dcid=000000000000000b scid=000000000000000d tok= len=1207 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=939
rx_pkt conn.c:705 serv conn 0:000000000000000b state conn_idle -> conn_opng
update_act_scid conn.c:503 hshk switch to scid 0:e7409dc685ba30ae for serv conn (was 0:000000000000000b)
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.169 rx_crypto conn.c:583 serv conn 0:e7409dc685ba30ae state conn_opng -> conn_estb
tx conn.c:429 data TX on serv conn 0:e7409dc685ba30ae strm -4 w/1 pkt in queue
enc_pkt pkt.c:395 hshk switch to scid 0:0646d01c5771f6c4 for serv conn (was 0:e7409dc685ba30ae)
update_act_scid conn.c:503 hshk switch to scid 0:0646d01c5771f6c4 for serv conn (was 0:e7409dc685ba30ae)
0.169 log_pkt pkt.c:176 TX to=127.0.0.1:4988 0xff=Initial vers=0xff00000f dcid=000000000000000d scid=0646d01c5771f6c4 tok=1375f1bc669decaec148221c372c700f032b1b1e4af7fa74f27dadf7368818fce7409dc685ba30ae 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:0646d01c5771f6c4
log_sent_pkts conn.c:229 epoch 0 unacked: *0
tx conn.c:429 data TX on serv conn 0:0646d01c5771f6c4 strm -2 w/2 pkts in queue
0.169 log_pkt pkt.c:186 TX to=127.0.0.1:4988 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=0646d01c5771f6c4 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:0646d01c5771f6c4
0.169 log_pkt pkt.c:186 TX to=127.0.0.1:4988 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=0646d01c5771f6c4 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:0646d01c5771f6c4
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.287 log_pkt pkt.c:123 RX from=127.0.0.1:4988 len=1216 0xff=Initial vers=0xff00000f dcid=0646d01c5771f6c4 scid=000000000000000d tok= len=1207 nr=4
dec_ack_frame frame.c:391 ACK lg=0 delay=0 (0 usec) cnt=0 block=0 [0]
on_pkt_acked recovery.c:506 stream -4 fully acked
detect_lost_pkts recovery.c:210 in_flight=1688 (-299), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.121983 (+0.121983), rttvar=0.060991 (+0.060991)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.121983 sec on serv conn 0:0646d01c5771f6c4
dec_frames frame.c:895 PADDING len=1181
tx conn.c:429 data TX on serv conn 0:0646d01c5771f6c4 strm -2 w/2 pkts in queue
log_sent_pkts conn.c:229 epoch 2 unacked: *0 *1
0.410 on_ld_alarm recovery.c:226 crypto RTX #1 on serv conn 0:0646d01c5771f6c4
detect_lost_pkts recovery.c:210 in_flight=1688 (+0), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.121983 (+0.000000), rttvar=0.060991 (+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.121983 (+0.000000), rttvar=0.060991 (+0.000000)
tx conn.c:429 data TX on serv conn 0:0646d01c5771f6c4 strm -2 w/2 pkts in queue
0.410 log_pkt pkt.c:186 TX to=127.0.0.1:4988 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=0646d01c5771f6c4 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=1252 (+1252), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.121983 (+0.000000), rttvar=0.060991 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.487931 sec on serv conn 0:0646d01c5771f6c4
0.410 log_pkt pkt.c:186 TX to=127.0.0.1:4988 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=0646d01c5771f6c4 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=1688 (+436), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.121983 (+0.000000), rttvar=0.060991 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.487931 sec on serv conn 0:0646d01c5771f6c4
log_sent_pkts conn.c:229 epoch 2 unacked: *0 *1 *2 *3
0.541 log_pkt pkt.c:133 RX from=127.0.0.1:4988 len=104 0xfd=Handshake vers=0xff00000f dcid=0646d01c5771f6c4 scid=000000000000000d len=96 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=1688 (+0), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.153729 (+0.031746), rttvar=0.109235 (+0.048244)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.176301 sec on serv conn 0:0646d01c5771f6c4
dec_frames frame.c:895 PADDING len=15
tx conn.c:429 data TX on serv conn 0:0646d01c5771f6c4 strm -2 w/2 pkts in queue
log_sent_pkts conn.c:229 epoch 2 unacked: *0 *2 *3
0.542 log_pkt pkt.c:194 TX to=127.0.0.1:4988 0x30=Short kyph=0 dcid=000000000000000d nr=0
enc_new_token_frame frame.c:1498 NEW_TOKEN len=40 tok=1375f1bc669decaec148221c372c700f032b1b1e4af7fa74f27dadf7368818fce7409dc685ba30ae
enc_new_cid_frame frame.c:1477 NEW_CONNECTION_ID seq=1 len=8 cid=1:31e53a1e6609babd tok=746d5c35158a23c2a7c7e485a290995c
on_pkt_sent recovery.c:311 in_flight=1783 (+95), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.153729 (+0.000000), rttvar=0.109235 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.176301 sec on serv conn 0:0646d01c5771f6c4
0.567 ack_alarm pn.c:56 ACK timer fired on serv conn 0:0646d01c5771f6c4 epoch 2
0.567 log_pkt pkt.c:186 TX to=127.0.0.1:4988 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=0646d01c5771f6c4 len=0 nr=4
enc_ack_frame frame.c:1171 ACK lg=0 delay=3224 (25792 usec) cnt=0 block=0 [0]
0.690 log_pkt pkt.c:133 RX from=127.0.0.1:4988 len=49 0xfd=Handshake vers=0xff00000f dcid=0646d01c5771f6c4 scid=000000000000000d len=41 nr=1
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=1783 (+0), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.200098 (+0.046369), rttvar=0.174665 (+0.065430)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.120305 sec on serv conn 0:0646d01c5771f6c4
dec_frames frame.c:895 PADDING len=15
tx conn.c:429 data TX on serv conn 0:0646d01c5771f6c4 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)
0.811 on_ld_alarm recovery.c:226 crypto RTX #1 on serv conn 0:0646d01c5771f6c4
detect_lost_pkts recovery.c:210 in_flight=1783 (+0), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.200098 (+0.000000), rttvar=0.174665 (+0.000000)
detect_lost_pkts recovery.c:210 in_flight=1783 (+0), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.200098 (+0.000000), rttvar=0.174665 (+0.000000)
tx conn.c:429 data TX on serv conn 0:0646d01c5771f6c4 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)
0.884 rx_pkts conn.c:952 pkt came from new peer 127.0.0.1:4987, probing
0.885 log_pkt pkt.c:141 RX from=127.0.0.1:4987 len=52 0x30=Short kyph=0 dcid=0646d01c5771f6c4 nr=0
new_stream stream.c:101 serv conn 0:0646d01c5771f6c4 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_frames frame.c:907 addtl stream or crypto frame at pos 24, copy
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_frames frame.c:895 PADDING len=15
rx conn.c:1066 q_rx_ready(0, 0) done, exiting event loop
q_rx_ready quic.c:667 serv conn 0:0646d01c5771f6c4 ready to rx
q_read quic.c:312 blocking read on serv conn 0:0646d01c5771f6c4
q_read quic.c:335 read 15 bytes on serv conn 0:0646d01c5771f6c4 strm 4
serve_cb server.c:110 conn 0:0646d01c5771f6c4 str 4 serving URL /5
q_write quic.c:271 writing 5 bytes in 1 buf on serv conn 0:0646d01c5771f6c4 strm 4
tx conn.c:429 data TX on serv conn 0:0646d01c5771f6c4 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)
tx conn.c:429 data TX on serv conn 0:0646d01c5771f6c4 strm 4 w/1 pkt in queue
0.885 log_pkt pkt.c:194 TX to=127.0.0.1:4987 0x31=Short kyph=0 dcid=000000000000000d nr=1
enc_ack_frame frame.c:1171 ACK lg=0 delay=59 (472 usec) cnt=0 block=0 [0]
enc_path_challenge_frame frame.c:1448 PATH_CHALLENGE data=4dc72b397437b561
enc_padding_frame frame.c:1099 PADDING len=24
log_stream_or_crypto_frame frame.c:113 STREAM 0x12=LEN id=4/20 off=0/8192 len=5 coff=0/16384
enc_path_challenge_frame frame.c:1448 PATH_CHALLENGE data=4dc72b397437b561
on_pkt_sent recovery.c:311 in_flight=1861 (+78), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.200098 (+0.000000), rttvar=0.174665 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.325444 sec on serv conn 0:0646d01c5771f6c4
log_sent_pkts conn.c:229 epoch 1/3 unacked: 0 *1
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3 (4)
0.885 log_pkt pkt.c:194 TX to=127.0.0.1:4987 0x36=Short kyph=0 dcid=000000000000000d nr=2
enc_path_challenge_frame frame.c:1448 PATH_CHALLENGE data=4dc72b397437b561
on_pkt_sent recovery.c:311 in_flight=1896 (+35), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.200098 (+0.000000), rttvar=0.174665 (+0.000000)
set_ld_timer recovery.c:134 crypto RTX alarm in 0.325444 sec on serv conn 0:0646d01c5771f6c4
1.033 rx_pkts conn.c:952 pkt came from new peer 127.0.0.1:4988, probing
1.033 log_pkt pkt.c:141 RX from=127.0.0.1:4988 len=34 0x30=Short kyph=0 dcid=0646d01c5771f6c4 nr=1
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=1801 (-95), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.236547 (+0.036449), rttvar=0.203897 (+0.029232)
set_ld_timer recovery.c:129 ignoring crypto RTX alarm in -0.149755 sec on serv conn 0:0646d01c5771f6c4
dec_frames frame.c:895 PADDING len=15
tx conn.c:429 data TX on serv conn 0:0646d01c5771f6c4 strm -2 w/2 pkts in queue
log_sent_pkts conn.c:229 epoch 1/3 unacked: *1 2
log_sent_pkts conn.c:229 epoch 2 unacked: *2 *3 (4)
tx conn.c:429 data TX on serv conn 0:0646d01c5771f6c4 strm 4 w/1 pkt in queue
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.033 log_pkt pkt.c:194 TX to=127.0.0.1:4988 0x30=Short kyph=0 dcid=000000000000000d nr=3
enc_path_challenge_frame frame.c:1448 PATH_CHALLENGE data=a66e5e1c859011b2
on_pkt_sent recovery.c:311 in_flight=1836 (+35), cwnd=6000 (+0), ssthresh=6000 (+0), srtt=0.236547 (+0.000000), rttvar=0.203897 (+0.000000)
set_ld_timer recovery.c:129 ignoring crypto RTX alarm in -0.149755 sec on serv conn 0:0646d01c5771f6c4
server: ev.c:3340: timers_reify: Assertion `("libev: negative ev_timer repeat value found while processing timers", w->repeat > 0.)' failed.
from quant.
kenmcmil
commented on July 30, 2024
By the way, I have a test that reproduces this error about half the time. Would it help if I posted a binary?
from quant.
kenmcmil
commented on July 30, 2024
FWIW, here's a binary for Ubuntu 18.08. I think it needs the libpicotls in your library path. Run it like this, after starting the server on port 4443:
./build/quic_server_test_stream seed=XXX
where XXX is a number.
from quant.
kenmcmil
commented on July 30, 2024
Sorry, you also need this library in your library path.
from quant.
larseggert
commented on July 30, 2024
This should be fixed in 5b18270 based on the discussion in quicwg/base-drafts#2052. Closing this based on the assumption that it's fixed, please reopen if it still occurs.
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.