Skip to content
This repository has been archived by the owner on Sep 3, 2024. It is now read-only.

local_error 5 seen at times with RESET of streams #105

Closed
TimEvens opened this issue Dec 13, 2023 · 6 comments · Fixed by #109
Closed

local_error 5 seen at times with RESET of streams #105

TimEvens opened this issue Dec 13, 2023 · 6 comments · Fixed by #109
Assignees
@TimEvens
Labels
bug Something isn't working

Comments

@TimEvens
Copy link
Contributor 

[QCTRL] [QSES] [QUIC] conn_id: 5600765952 data_ctx_id: 5 closing stream stream_id: 46
[QCTRL] [QSES] [QUIC] Reset stream_id: 46 conn_id: 5600765952
[QCTRL] [QSES] [QUIC] Replacing stream using RESET; conn_id: 5600765952 data_ctx_id: 5 existing_stream: 0 write buf drops: 0 tx_queue_discards: 0
[QCTRL] [QSES] [QUIC] conn_id: 5600765952 data_ctx_id: 5 create new stream with stream_id: 58
[QCTRL] [QSES] [QUIC] conn_id: 5600765952 data_ctx_id: 7 closing stream stream_id: 54
[QCTRL] [QSES] [QUIC] Reset stream_id: 54 conn_id: 5600765952
[QCTRL] [QSES] [QUIC] Replacing stream using RESET; conn_id: 5600765952 data_ctx_id: 7 existing_stream: 0 write buf drops: 0 tx_queue_discards: 0
[QCTRL] [QSES] [QUIC] conn_id: 5600765952 data_ctx_id: 7 create new stream with stream_id: 62
[QCTRL] [QSES] [QUIC] conn_id: 5600765952 data_ctx_id: 6 closing stream stream_id: 50
[QCTRL] [QSES] [QUIC] Reset stream_id: 50 conn_id: 5600765952
[QCTRL] [QSES] [QUIC] Replacing stream using RESET; conn_id: 5600765952 data_ctx_id: 6 existing_stream: 0 write buf drops: 0 tx_queue_discards: 0
[QCTRL] [QSES] [QUIC] conn_id: 5600765952 data_ctx_id: 6 create new stream with stream_id: 66
[QCTRL] [QSES] [QUIC] conn_id: 5600765952 stream_id: 58 pri: 6 CB TX delta 419 ms count: 1 tx_queue_size: 12
[QCTRL] [QSES] [QUIC] Closing connection conn_id: 5600765952 stream_id: 0 local_error: 5 remote_error: 0 app_error: 0 remote: 15.197.244.172
[QCTRL] [QSES] [QUIC] Delete data context 0 in conn_id: 5600765952
[QCTRL] [QSES] [QUIC] Delete default context for conn_id: 5600765952, closing connection
[QCTRL] [QSES] connection_status: cid: 5600765952 status: 3
[QCTRL] [QSES] Received disconnect from transport for context: 5600765952
[QCTRL] [QSES] Shutting down context: 5600765952
[QCTRL] [QSES] [QUIC] picoquic ended with 0
@TimEvens
Copy link
Contributor Author

TimEvens commented Dec 13, 2023 •
edited
Loading

Local error 5 is PICOQUIC_TRANSPORT_STREAM_STATE_ERROR. This is set only for one of the below:

frames.c line 60

else if (stream_id < cnx->next_stream_id[STREAM_TYPE_FROM_ID(stream_id)]) {
        /* Protocol error, stream already closed */
        picoquic_connection_error(cnx, PICOQUIC_TRANSPORT_STREAM_STATE_ERROR, 0);

frames.c line 805

else if (!IS_BIDIR_STREAM_ID(stream_id) && !IS_LOCAL_STREAM_ID(stream_id, cnx->client_mode)) {
        picoquic_connection_error(cnx, PICOQUIC_TRANSPORT_STREAM_STATE_ERROR,
            picoquic_frame_type_stop_sending);
        bytes = NULL;

@TimEvens
Copy link
Contributor Author

I've ran through a ton of tests and I cannot reproduce the issue.

@TimEvens TimEvens self-assigned this Dec 15, 2023
@TimEvens TimEvens added the bug Something isn't working label Dec 15, 2023
TimEvens added a commit that referenced this issue Dec 15, 2023
@TimEvens
Fix mark active/ready to not mark old stream active
74f52f3 
Resolves #105
@TimEvens
Copy link
Contributor Author

Very hard to reproduce due to it being a race condition. I believe there is only one place where the race condition could happen to cause an old stream to be marked active (creating a new stream in picoquic) on a stream that was just reset. This is a race condition of pending pq_runner function calls at the same time as a reset happened. If the reset happened before running pq_runnner then the previous stream would be marked active after it was reset.

The fix is to change how threaded functions mark a stream active.

@TimEvens TimEvens mentioned this issue Dec 15, 2023
Merged
@TimEvens
Copy link
Contributor Author

Issue still present. Looks to be in picoquic causing the issue. Below is a stack trace of when it happens.

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x0000007ff7c3caa0 in __GI_abort () at abort.c:79
#2  0x00000055555f3184 in picoquic_create_missing_streams (is_remote=0, stream_id=423, cnx=0x7fc8058710) at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/frames.c:62
#3  picoquic_create_missing_streams (cnx=0x7fc8058710, stream_id=423, is_remote=<optimized out>) at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/frames.c:42
#4  0x00000055555f3a14 in picoquic_find_or_create_stream (is_remote=0, stream_id=423, cnx=0x7fc8058710) at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/frames.c:175
#5  picoquic_process_ack_of_reset_stream_frame (cnx=cnx@entry=0x7fc8058710, bytes=<optimized out>, bytes@entry=0x7fc80f942e "\004A\247", bytes_size=27, consumed=consumed@entry=0x7fdcff77d8)
    at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/frames.c:326
#6  0x00000055555fc960 in picoquic_process_ack_of_frames (cnx=cnx@entry=0x7fc8058710, p=p@entry=0x7fc80f9360, is_spurious=is_spurious@entry=0, current_time=current_time@entry=1702675297877257)
    at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/frames.c:3288
#7  0x00000055555fd4c8 in picoquic_process_ack_range (pc=<optimized out>, packet_data=<optimized out>, current_time=<optimized out>, ppacket=<optimized out>, range=312, highest=137070, pkt_ctx=<optimized out>, cnx=<optimized out>)
    at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/frames.c:3395
#8  picoquic_decode_ack_frame (cnx=cnx@entry=0x7fc8058710, bytes=0x7fc80e5c56 "\200\002\027p", bytes_max=bytes_max@entry=0x7fc80e5c67 "\363\t", current_time=current_time@entry=1702675297877257, epoch=epoch@entry=3, is_ecn=<optimized out>,
    has_path_id=<optimized out>, packet_data=<optimized out>) at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/frames.c:3500
#9  0x00000055555fd9b0 in picoquic_decode_frames (cnx=cnx@entry=0x7fc8058710, path_x=<optimized out>, bytes=<optimized out>, bytes_maxsize=<optimized out>, received_data=received_data@entry=0x7fc80e5c00, epoch=3,
    addr_from=addr_from@entry=0x7fdcff8000, addr_to=addr_to@entry=0x7fdcff8080, pn64=<optimized out>, path_is_not_allocated=<optimized out>, path_is_not_allocated@entry=0, current_time=<optimized out>, current_time@entry=1702675297877257)
    at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/frames.c:5451
#10 0x000000555560ab98 in picoquic_incoming_1rtt (cnx=0x7fc8058710, path_id=0, bytes=bytes@entry=0x7fc80e5c40 "b\340\314\071G@\237\204\b\002\027\r\003\200\002\027x@\214", received_data=received_data@entry=0x7fc80e5c00, ph=ph@entry=0x7fdcff7cf8,
    addr_from=addr_from@entry=0x7fdcff8000, addr_to=addr_to@entry=0x7fdcff8080, if_index_to=if_index_to@entry=2, received_ecn=<optimized out>, received_ecn@entry=0 '\000', path_is_not_allocated=<optimized out>, path_is_not_allocated@entry=0,
    current_time=<optimized out>, current_time@entry=1702675297877257) at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/packet.c:2030
#11 0x000000555560b4c0 in picoquic_incoming_segment (quic=quic@entry=0x555586e4d0,
    raw_bytes=raw_bytes@entry=0x7fdcff8200 "a\340\314\071G@\237\204\b\346\260\341\b\210>\221\362\202Ҏ\333\006R|\"\036\020\325\227S\241={n\f\327g\360\270\253hU \347\276W\261\036%Y\354|\355\373\261\310\001\\_\r»\261\360\241+\337ۦ\355\264\v|\306\n\322W\300FD\336\025\336\070\357\064\n\257\066\300\247\376+f/瓨6\214\210o\274VxbVl\337~\004\207\373\254\223\365\353\367W\036\a\003\302D\344\067\336(Fq\234+\366\304\351\301\034i\006v\235\343\213\027n\222~\376Ο\230iƮ\264\376h\372\005ΦR\314\fXM#\312\347 \276\343J)\224\374o\211\060BV\226\270\006\376\001\354;\242(\024\037\r\316\320X\351j", <incomplete sequence \333>..., length=length@entry=55, packet_length=packet_length@entry=55, consumed=consumed@entry=0x7fdcff7e30,
    addr_from=addr_from@entry=0x7fdcff8000, addr_to=addr_to@entry=0x7fdcff8080, if_index_to=if_index_to@entry=2, received_ecn=<optimized out>, received_ecn@entry=0 '\000', current_time=<optimized out>, current_time@entry=1702675297877257,
    receive_time=<optimized out>, receive_time@entry=1702675297877257, previous_dest_id=<optimized out>, previous_dest_id@entry=0x7fdcff7e38, first_cnx=<optimized out>, first_cnx@entry=0x7fdcff7fd8)
    at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/packet.c:2331
#12 0x000000555560bbdc in picoquic_incoming_packet_ex (quic=quic@entry=0x555586e4d0,
    bytes=bytes@entry=0x7fdcff8200 "a\340\314\071G@\237\204\b\346\260\341\b\210>\221\362\202Ҏ\333\006R|\"\036\020\325\227S\241={n\f\327g\360\270\253hU \347\276W\261\036%Y\354|\355\373\261\310\001\\_\r»\261\360\241+\337ۦ\355\264\v|\306\n\322W\300FD\336\025\336\070\357\064\n\257\066\300\247\376+f/瓨6\214\210o\274VxbVl\337~\004\207\373\254\223\365\353\367W\036\a\003\302D\344\067\336(Fq\234+\366\304\351\301\034i\006v\235\343\213\027n\222~\376Ο\230iƮ\264\376h\372\005ΦR\314\fXM#\312\347 \276\343J)\224\374o\211\060BV\226\270\006\376\001\354;\242(\024\037\r\316\320X\351j", <incomplete sequence \333>..., packet_length=packet_length@entry=55, addr_from=addr_from@entry=0x7fdcff8000, addr_to=addr_to@entry=0x7fdcff8080, if_index_to=2,
    received_ecn=0 '\000', first_cnx=first_cnx@entry=0x7fdcff7fd8, current_time=current_time@entry=1702675297877257) at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/packet.c:2437
#13 0x0000005555620544 in picoquic_packet_loop (quic=<optimized out>, local_port=<optimized out>, local_af=<optimized out>, dest_if=0, socket_buffer_size=2000000, do_not_use_gso=<optimized out>,
    loop_callback=0x55555d1bec <pq_loop_cb(st_picoquic_quic_t*, picoquic_packet_loop_cb_enum, void*, void*)>, loop_callback_ctx=0x555586bf80) at /ws/dependencies/libquicr/dependencies/transport/dependencies/picoquic/picoquic/sockloop.c:329
#14 0x00000055555d5e44 in qtransport::PicoQuicTransport::server (this=0x555586bf80) at /ws/dependencies/libquicr/dependencies/transport/src/transport_picoquic.cpp:1387
#15 0x00000055555e9af4 in std::__invoke_impl<void, void (qtransport::PicoQuicTransport::*)(), qtransport::PicoQuicTransport*> (
    __f=@0x5555874220: (void (qtransport::PicoQuicTransport::*)(qtransport::PicoQuicTransport * const)) 0x55555d5dfc <qtransport::PicoQuicTransport::server()>, __t=@0x5555874218: 0x555586bf80) at /usr/include/c++/10/bits/invoke.h:73
#16 0x00000055555e9850 in std::__invoke<void (qtransport::PicoQuicTransport::*)(), qtransport::PicoQuicTransport*> (
    __fn=@0x5555874220: (void (qtransport::PicoQuicTransport::*)(qtransport::PicoQuicTransport * const)) 0x55555d5dfc <qtransport::PicoQuicTransport::server()>) at /usr/include/c++/10/bits/invoke.h:95
#17 0x00000055555e9690 in std::thread::_Invoker<std::tuple<void (qtransport::PicoQuicTransport::*)(), qtransport::PicoQuicTransport*> >::_M_invoke<0ul, 1ul> (this=0x5555874218) at /usr/include/c++/10/thread:264
#18 0x00000055555e9594 in std::thread::_Invoker<std::tuple<void (qtransport::PicoQuicTransport::*)(), qtransport::PicoQuicTransport*> >::operator() (this=0x5555874218) at /usr/include/c++/10/thread:271
#19 0x00000055555e94f0 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (qtransport::PicoQuicTransport::*)(), qtransport::PicoQuicTransport*> > >::_M_run (this=0x5555874210) at /usr/include/c++/10/thread:215
#20 0x0000007ff7e7ecac in ?? () from /lib/aarch64-linux-gnu/libstdc++.so.6
#21 0x0000007ff7f94648 in start_thread (arg=0x7fdcff8a40) at pthread_create.c:477
#22 0x0000007ff7ceec1c in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:78

@TimEvens
Copy link
Contributor Author

Problem appears to be in picoquic handling of reset ack. Spoke briefly to Christian and opened issue private-octopus/picoquic#1597.

@TimEvens
Copy link
Contributor Author

private-octopus/picoquic#1598 resolves the issue.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@TimEvens TimEvens

Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Upgrade Picoquic and fix stream local_error 5 Quicr/transport
1 participant
@TimEvens