search

NTAP / quant

QUIC implementation for POSIX and IoT platforms
BSD 2-Clause "Simplified" License
289 stars 35 forks source link

tx_tlp conn.c:468 ABORT: assertion failed #25

Closed kenmcmil closed 5 years ago

kenmcmil commented 5 years ago

Here's a log with an assertion failure. I can't tell what's going wrong here. It seems like maybe trying to send data on a stream that doesn't exist?


0.030   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.032   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.148   rx_pkts conn.c:918 new serv conn on port 4443 from 127.0.0.1:4987 w/cid=0:0000000000000003
        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:0000000000000003 on port 4443 created
        new_conn conn.c:1313 serv conn 0:0000000000000003 state conn_clsd -> conn_idle
0.148   log_pkt pkt.c:123 RX from=127.0.0.1:4987 len=1216 0xff=Initial vers=0xff00000f dcid=0000000000000003 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:0000000000000003 state conn_idle -> conn_opng
        update_act_scid conn.c:503 hshk switch to scid 0:015df21cc269b634 for serv conn (was 0:0000000000000003)
        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.151   rx_crypto conn.c:583 serv conn 0:015df21cc269b634 state conn_opng -> conn_estb
        tx conn.c:429 data TX on serv conn 0:015df21cc269b634 strm -4 w/1 pkt in queue
        enc_pkt pkt.c:395 hshk switch to scid 0:82063f2ad8736687 for serv conn (was 0:015df21cc269b634)
        update_act_scid conn.c:503 hshk switch to scid 0:82063f2ad8736687 for serv conn (was 0:015df21cc269b634)
0.151   log_pkt pkt.c:176 TX to=127.0.0.1:4987 0xff=Initial vers=0xff00000f dcid=000000000000000d scid=82063f2ad8736687 tok=0847c4c8e09c14395cbba3e76f8945a06a0c491ef11dbca37cb7507deecbacff015df21cc269b634 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:82063f2ad8736687
        log_sent_pkts conn.c:229 epoch 0 unacked: *0 
        tx conn.c:429 data TX on serv conn 0:82063f2ad8736687 strm -2 w/2 pkts in queue
0.151   log_pkt pkt.c:186 TX to=127.0.0.1:4987 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=82063f2ad8736687 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:82063f2ad8736687
0.152   log_pkt pkt.c:186 TX to=127.0.0.1:4987 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=82063f2ad8736687 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:82063f2ad8736687
        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.250   log_pkt pkt.c:133 RX from=127.0.0.1:4987 len=49 0xfd=Handshake vers=0xff00000f dcid=82063f2ad8736687 scid=000000000000000d len=41 nr=0
        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=735 (-1252), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.101899 (+0.101899), rttvar=0.050950 (+0.050950)
        set_ld_timer recovery.c:134 crypto RTX alarm in 0.101899 sec on serv conn 0:82063f2ad8736687
        dec_frames frame.c:895 PADDING len=15
        tx conn.c:429 data TX on serv conn 0:82063f2ad8736687 strm -4 w/1 pkt in queue
        log_sent_pkts conn.c:229 epoch 0 unacked: *0 
        log_sent_pkts conn.c:229 epoch 2 unacked: *1 
        tx conn.c:429 data TX on serv conn 0:82063f2ad8736687 strm -2 w/2 pkts in queue
        log_sent_pkts conn.c:229 epoch 0 unacked: *0 
        log_sent_pkts conn.c:229 epoch 2 unacked: *1 
0.353   on_ld_alarm recovery.c:226 crypto RTX #1 on serv conn 0:82063f2ad8736687
        detect_lost_pkts recovery.c:171 pkt 0 considered lost
        detect_lost_pkts recovery.c:210 in_flight=436 (-299), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.101899 (+0.000000), rttvar=0.050950 (+0.000000)
        detect_lost_pkts recovery.c:210 in_flight=436 (+0), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.101899 (+0.000000), rttvar=0.050950 (+0.000000)
        tx conn.c:429 data TX on serv conn 0:82063f2ad8736687 strm -4 w/1 pkt in queue
0.353   log_pkt pkt.c:176 TX to=127.0.0.1:4987 0xff=Initial vers=0xff00000f dcid=000000000000000d scid=82063f2ad8736687 tok=0847c4c8e09c14395cbba3e76f8945a06a0c491ef11dbca37cb7507deecbacff015df21cc269b634 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=735 (+299), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.101899 (+0.000000), rttvar=0.050950 (+0.000000)
        set_ld_timer recovery.c:134 crypto RTX alarm in 0.407597 sec on serv conn 0:82063f2ad8736687
        log_sent_pkts conn.c:229 epoch 0 unacked: *0 *1 
        log_sent_pkts conn.c:229 epoch 2 unacked: *1 
        tx conn.c:429 data TX on serv conn 0:82063f2ad8736687 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: *1 
0.416   log_pkt pkt.c:123 RX from=127.0.0.1:4987 len=1216 0xff=Initial vers=0xff00000f dcid=82063f2ad8736687 scid=000000000000000d tok= len=1207 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 1
        detect_lost_pkts recovery.c:210 in_flight=735 (+0), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.122720 (+0.020821), rttvar=0.079854 (+0.028905)
        set_ld_timer recovery.c:134 crypto RTX alarm in 0.181780 sec on serv conn 0:82063f2ad8736687
        dec_frames frame.c:895 PADDING len=1181
        tx conn.c:429 data TX on serv conn 0:82063f2ad8736687 strm -4 w/1 pkt in queue
        log_sent_pkts conn.c:229 epoch 0 unacked: *1 
        log_sent_pkts conn.c:229 epoch 2 unacked: *1 
        tx conn.c:429 data TX on serv conn 0:82063f2ad8736687 strm -2 w/2 pkts in queue
        log_sent_pkts conn.c:229 epoch 0 unacked: *1 
        log_sent_pkts conn.c:229 epoch 2 unacked: *1 
0.505   log_pkt pkt.c:141 RX from=127.0.0.1:4987 len=56 0x30=Short kyph=0 dcid=82063f2ad8736687 nr=0
        rx_pkts conn.c:998 received invalid 56-byte 0x30-type pkt, ignoring
0.598   on_ld_alarm recovery.c:226 crypto RTX #1 on serv conn 0:82063f2ad8736687
        detect_lost_pkts recovery.c:210 in_flight=735 (+0), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.122720 (+0.000000), rttvar=0.079854 (+0.000000)
        detect_lost_pkts recovery.c:210 in_flight=735 (+0), cwnd=12000 (+0), ssthresh=0 (+0), srtt=0.122720 (+0.000000), rttvar=0.079854 (+0.000000)
        tx conn.c:429 data TX on serv conn 0:82063f2ad8736687 strm -4 w/1 pkt in queue
        log_sent_pkts conn.c:229 epoch 0 unacked: *1 
        log_sent_pkts conn.c:229 epoch 2 unacked: *1 
        tx conn.c:429 data TX on serv conn 0:82063f2ad8736687 strm -2 w/2 pkts in queue
        log_sent_pkts conn.c:229 epoch 0 unacked: *1 
        log_sent_pkts conn.c:229 epoch 2 unacked: *1 
0.750   log_pkt pkt.c:133 RX from=127.0.0.1:4987 len=104 0xfd=Handshake vers=0xff00000f dcid=82063f2ad8736687 scid=000000000000000d len=96 nr=2
        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 -2 fully acked
        detect_lost_pkts recovery.c:210 in_flight=299 (-436), cwnd=12436 (+436), ssthresh=0 (+0), srtt=0.182664 (+0.059944), rttvar=0.179779 (+0.099925)
        set_ld_timer recovery.c:129 ignoring crypto RTX alarm in -0.032137 sec on serv conn 0:82063f2ad8736687
        log_stream_or_crypto_frame frame.c:118 CRYPTO 0x18 off=0 len=52 [seq]
        dec_frames frame.c:895 PADDING len=15
        tx conn.c:429 data TX on serv conn 0:82063f2ad8736687 strm -4 w/1 pkt in queue
        log_sent_pkts conn.c:229 epoch 0 unacked: *1 
0.751   log_pkt pkt.c:194 TX to=127.0.0.1:4987 0x31=Short kyph=0 dcid=000000000000000d nr=0
        enc_new_token_frame frame.c:1498 NEW_TOKEN len=40 tok=0847c4c8e09c14395cbba3e76f8945a06a0c491ef11dbca37cb7507deecbacff015df21cc269b634
        enc_new_cid_frame frame.c:1477 NEW_CONNECTION_ID seq=1 len=8 cid=1:b80cb41b2e5ecf3a tok=dc85f9d14a46086b93e9c368de18ca1d
        on_pkt_sent recovery.c:311 in_flight=394 (+95), cwnd=12436 (+0), ssthresh=0 (+0), srtt=0.182664 (+0.000000), rttvar=0.179779 (+0.000000)
        set_ld_timer recovery.c:129 ignoring crypto RTX alarm in -0.032137 sec on serv conn 0:82063f2ad8736687
0.776   ack_alarm pn.c:56 ACK timer fired on serv conn 0:82063f2ad8736687 epoch 2
0.776   log_pkt pkt.c:186 TX to=127.0.0.1:4987 0xfd=Handshake vers=0xff00000f dcid=000000000000000d scid=82063f2ad8736687 len=0 nr=2
        enc_ack_frame frame.c:1171 ACK lg=2 delay=3215 (25720 usec) cnt=1 block=0 [2]
        enc_ack_frame frame.c:1164 ACK gap=0 block=0 [0]
0.888   log_pkt pkt.c:123 RX from=127.0.0.1:4987 len=1216 0xff=Initial vers=0xff00000f dcid=82063f2ad8736687 scid=000000000000000d tok= len=1207 nr=2
        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=95 (-299), cwnd=12735 (+299), ssthresh=0 (+0), srtt=0.226684 (+0.044020), rttvar=0.222874 (+0.043095)
        set_ld_timer recovery.c:134 TLP alarm in 0.227669 sec on serv conn 0:82063f2ad8736687
        dec_frames frame.c:895 PADDING len=1181
0.980   log_pkt pkt.c:141 RX from=127.0.0.1:4987 len=41 0x30=Short kyph=0 dcid=82063f2ad8736687 nr=2
        new_stream stream.c:101 serv conn 0:82063f2ad8736687 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:895 PADDING len=15
1.005   ack_alarm pn.c:56 ACK timer fired on serv conn 0:82063f2ad8736687 epoch 3
1.005   log_pkt pkt.c:194 TX to=127.0.0.1:4987 0x33=Short kyph=0 dcid=000000000000000d nr=1
        enc_ack_frame frame.c:1171 ACK lg=2 delay=3186 (25488 usec) cnt=0 block=0 [2]
1.116   on_ld_alarm recovery.c:239 TLP alarm #0 on serv conn 0:82063f2ad8736687
1.116   tx_tlp conn.c:468 ABORT: assertion failed 
        meta(v).stream 
        have stream 0 [errno 17 = File exists]
        /usr/lib/x86_64-linux-gnu/libasan.so.4(+0x558c0) [0x7ff7133de8c0]
        util_die at /home/mcmillan/projects/quant/Debug/external/warp-prefix/src/warp/lib/src/util.c:224
        tx_tlp at /home/mcmillan/projects/quant/lib/src/conn.c:470
        on_ld_alarm at /home/mcmillan/projects/quant/lib/src/recovery.c:253
        /usr/lib/x86_64-linux-gnu/libev.so.4(ev_invoke_pending+0x53) [0x7ff712559d73]
        /usr/lib/x86_64-linux-gnu/libev.so.4(ev_run+0x9ee) [0x7ff71255d3de]
        q_rx_ready at /home/mcmillan/projects/quant/lib/src/quic.c:660 (discriminator 2)
        main at /home/mcmillan/projects/quant/bin/server.c:246
        /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7) [0x7ff711250b97]
        _start at ??:?
larseggert commented 5 years ago

This should be fixed by 751339c218889d73fded72905408ee56f78b4df9. Please reopen if it still occurs.