Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Assertion in HQ Fatal: HQFrame.cc:295: failed assertion sizeof(buf) > len #4688

Closed
scw00 opened this issue Dec 6, 2018 · 6 comments
Closed
Labels
Projects
Milestone

Comments

@scw00
Copy link
Member

scw00 commented Dec 6, 2018

0x00007ffff42bd428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
54 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0 0x00007ffff42bd428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#1 0x00007ffff42bf02a in __GI_abort () at abort.c:89
#2 0x00007ffff6a5481d in ink_abort (message_format=0x7ffff6b440a0 "%s:%d: failed assertion %s") at ink_error.cc:99
#3 0x00007ffff6a4c6a0 in _ink_assert (expression=0x11333a0 "sizeof(buf) > len", file=0x1133120 "HQFrame.cc", line=295) at ink_assert.cc:37
#4 0x0000000000de60fd in HQFrameFactory::fast_create (this=0x62600001e350, stream_io=..., len=13744632839234567870) at HQFrame.cc:295
#5 0x0000000000ddb3cd in HQFrameDispatcher::on_read_ready (this=0x62600001e338, stream_io=..., nread=@0x7fffeed894c0: 0) at HQFrameDispatcher.cc:74
#6 0x0000000000dd6259 in HQClientTransaction::_process_read_vio (this=0x62600001e100) at HQClientTransaction.cc:464
#7 0x0000000000dd3e6d in HQClientTransaction::do_io_read (this=0x62600001e100, c=0x7fffea7aa510, nbytes=0, buf=0x62600001e1a8) at HQClientTransaction.cc:228
#8 0x000000000080872b in HttpSM::attach_client_session (this=0x7fffea7aa510, client_vc=0x62600001e100, buffer_reader=0x62600001e1c0) at HttpSM.cc:529
#9 0x0000000000c70d22 in ProxyClientTransaction::new_transaction (this=0x62600001e100) at ProxyClientTransaction.cc:60
#10 0x0000000000dcf2b4 in QUICSimpleApp::main_event_handler (this=0x60c000017140, event=100, data=0x63400001cd30) at QUICSimpleApp.cc:77
#11 0x00000000006db9c8 in Continuation::handleEvent (this=0x60c000017140, event=100, data=0x63400001cd30) at /root/trafficserver/iocore/eventsystem/I_Continuation.h:165
#12 0x0000000000e5829d in QUICStream::_signal_read_event (this=0x63400001cb70) at QUICStream.cc:572
#13 0x0000000000e55d97 in QUICStream::recv (this=0x63400001cb70, frame=...) at QUICStream.cc:356
#14 0x0000000000e44497 in QUICStreamManager::_handle_frame (this=0x610000008a40, frame=...) at QUICStreamManager.cc:207
#15 0x0000000000e43ad6 in QUICStreamManager::handle_frame (this=0x610000008a40, level=QUICEncryptionLevel::ONE_RTT, frame=...) at QUICStreamManager.cc:151
#16 0x0000000000e27d93 in QUICFrameDispatcher::receive_frames (this=0x62600000f100, level=QUICEncryptionLevel::ONE_RTT, payload=0x61d000014a80 "\022", size=1216, ack_only=@0x7fffeed8cce0: false,
is_flow_controlled=@0x7fffeed8cd20: true, has_non_probing_frame=0x7fffeed8cfa0) at QUICFrameDispatcher.cc:83
#17 0x0000000000d444a2 in QUICNetVConnection::_recv_and_ack (this=0x7fffea9dcc70, packet=..., has_non_probing_frame=0x7fffeed8cfa0) at QUICNetVConnection.cc:1480
#18 0x0000000000d3d91e in QUICNetVConnection::_state_connection_established_process_protected_packet (this=0x7fffea9dcc70, packet=std::unique_ptr containing 0x62900003ff40)
at QUICNetVConnection.cc:1049
#19 0x0000000000d3e46f in QUICNetVConnection::_state_connection_established_receive_packet (this=0x7fffea9dcc70) at QUICNetVConnection.cc:1101
#20 0x0000000000d38182 in QUICNetVConnection::state_connection_established (this=0x7fffea9dcc70, event=2500, data=0x0) at QUICNetVConnection.cc:662
#21 0x00000000006db9c8 in Continuation::handleEvent (this=0x7fffea9dcc70, event=2500, data=0x0) at /root/trafficserver/iocore/eventsystem/I_Continuation.h:165
#22 0x0000000000d3a170 in QUICNetVConnection::net_read_io (this=0x7fffea9dcc70, nh=0x7fffeed95530, lthread=0x7fffeed91800) at QUICNetVConnection.cc:817
#23 0x0000000000cf95b6 in NetHandler::process_ready_list (this=0x7fffeed95530) at UnixNet.cc:396
#24 0x0000000000cfae06 in NetHandler::waitForActivity (this=0x7fffeed95530, timeout=2484836) at UnixNet.cc:529
#25 0x0000000000dc5450 in EThread::execute_regular (this=0x7fffeed91800) at UnixEThread.cc:273
#26 0x0000000000dc5c6f in EThread::execute (this=0x7fffeed91800) at UnixEThread.cc:326
#27 0x0000000000dc2346 in spawn_thread_internal (a=0x606000033380) at Thread.cc:92
#28 0x00007ffff51066ba in start_thread (arg=0x7fffeed8e700) at pthread_create.c:333
#29 0x00007ffff438f41d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

@maskit Can you please have a look ?

@scw00
Copy link
Member Author

scw00 commented Dec 6, 2018

(gdb) bt full
#0  0x00007ffff42bd428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
        resultvar = 0
        pid = 14568
        selftid = 14596
#1  0x00007ffff42bf02a in __GI_abort () at abort.c:89
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {0, 0, 0, 0, 0, 0, 18446744073709547520, 140737248272384, 140737343471288, 0, 0, 11760, 17594297523184, 0,
              0, 0}}, sa_flags = -1198171648, sa_restorer = 0xffffddaf15e}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007ffff6a5481d in ink_abort (message_format=0x7ffff6b440a0 "%s:%d: failed assertion `%s`") at ink_error.cc:99
        ap = <error reading variable ap (Cannot access memory at address 0xffffffffffffffc0)>
#3  0x00007ffff6a4c6a0 in _ink_assert (expression=0x11333a0 "sizeof(buf) > len", file=0x1133120 "HQFrame.cc", line=295) at ink_assert.cc:37
No locals.
#4  0x0000000000de60fd in HQFrameFactory::fast_create (this=0x62600001e350, stream_io=..., len=13744632839234567870) at HQFrame.cc:295
        buf = '\000' <repeats 14071 times>...
#5  0x0000000000ddb3cd in HQFrameDispatcher::on_read_ready (this=0x62600001e338, stream_io=..., nread=@0x7fffeed890b0: 0) at HQFrameDispatcher.cc:74
        type = HQFrameType::DATA
        handlers = std::vector of length 15393131311055, capacity 11141149662821 = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0,
          0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0,
          0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0,
          0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0,
          0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0,
          0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0...}
        frame = std::shared_ptr (empty) 0x0
        error = std::unique_ptr<HQError> containing 0x603000064090
#6  0x0000000000dd6259 in HQClientTransaction::_process_read_vio (this=0x62600001e100) at HQClientTransaction.cc:464
        nread = 0
        __FUNCTION__ = "_process_read_vio"
        lock = {m = {m_ptr = 0x62a0000154c0}, locked_p = true}
#7  0x0000000000dd3e6d in HQClientTransaction::do_io_read (this=0x62600001e100, c=0x7fffea7ba510, nbytes=0, buf=0x62600001e1a8) at HQClientTransaction.cc:228
No locals.
#8  0x000000000080872b in HttpSM::attach_client_session (this=0x7fffea7ba510, client_vc=0x62600001e100, buffer_reader=0x62600001e1c0) at HttpSM.cc:529
        netvc = 0x7fffea9dcc70
        ssl_vc = 0x0
        protocol_str = 0x1124d40 "hq"
#9  0x0000000000c70d22 in ProxyClientTransaction::new_transaction (this=0x62600001e100) at ProxyClientTransaction.cc:60
        __FUNCTION__ = "new_transaction"
        pi = 0x0
#10 0x0000000000dcf2b4 in QUICSimpleApp::main_event_handler (this=0x60c000017140, event=100, data=0x63400001cd30) at QUICSimpleApp.cc:77
        lock = {m = {m_ptr = 0x62a0000154c0}, locked_p = true}
        __FUNCTION__ = "main_event_handler"
        vio = 0x63400001cd30
        stream_io = 0x60700001f5f0
        stream_id = 0
        txn = 0x62600001e100
        dummy = 31 '\037'
#11 0x00000000006db9c8 in Continuation::handleEvent (this=0x60c000017140, event=100, data=0x63400001cd30) at /root/trafficserver/iocore/eventsystem/I_Continuation.h:165
No locals.
#12 0x0000000000e5829d in QUICStream::_signal_read_event (this=0x63400001cb70) at QUICStream.cc:572
        lock = {m = {m_ptr = 0x62a0000155a0}, lock_acquired = true}
---Type <return> to continue, or q <return> to quit---
        __FUNCTION__ = "_signal_read_event"
        event = 100
#13 0x0000000000e55d97 in QUICStream::recv (this=0x63400001cb70, frame=...) at QUICStream.cc:356
        __FUNCTION__ = "recv"
        ret = 0
        error = std::unique_ptr<QUICConnectionError> containing 0x0
        new_frame = std::shared_ptr (empty) 0x0
        stream_frame = std::shared_ptr (count 1, weak 0) 0x62a00002ef00
#14 0x0000000000e44497 in QUICStreamManager::_handle_frame (this=0x610000008a40, frame=...) at QUICStreamManager.cc:207
        stream = 0x63400001cb70
        application = 0x60c000017140
#15 0x0000000000e43ad6 in QUICStreamManager::handle_frame (this=0x610000008a40, level=QUICEncryptionLevel::ONE_RTT, frame=...) at QUICStreamManager.cc:151
        error = std::unique_ptr<QUICConnectionError> containing 0x0
        __FUNCTION__ = "handle_frame"
#16 0x0000000000e27d93 in QUICFrameDispatcher::receive_frames (this=0x62600000f100, level=QUICEncryptionLevel::ONE_RTT, payload=0x61d000013680 "\022", size=1216, ack_only=@0x7fffeed8c8d0: false,
    is_flow_controlled=@0x7fffeed8c910: true, has_non_probing_frame=0x7fffeed8cb90) at QUICFrameDispatcher.cc:83
        h = 0x610000008a40
        __for_range = std::vector of length 1, capacity 1 = {0x610000008a40}
        __for_begin = 0x610000008a40
        __for_end = 0x0
        type = QUICFrameType::STREAM
        handlers = std::vector of length 1, capacity 1 = {0x610000008a40}
        frame = std::shared_ptr (count 2, weak 0) 0x62a00002ef70
        cursor = 1216
        error = std::unique_ptr<QUICConnectionError> containing 0x0
        __FUNCTION__ = "receive_frames"
#17 0x0000000000d444a2 in QUICNetVConnection::_recv_and_ack (this=0x7fffea9dcc70, packet=..., has_non_probing_frame=0x7fffeed8cb90) at QUICNetVConnection.cc:1480
        payload = 0x61d000013680 "\022"
        size = 1216
        packet_num = 0
        level = QUICEncryptionLevel::ONE_RTT
        ack_only = false
        is_flow_controlled = true
        error = std::unique_ptr<QUICConnectionError> containing 0x0
        __FUNCTION__ = "_recv_and_ack"
#18 0x0000000000d3d91e in QUICNetVConnection::_state_connection_established_process_protected_packet (this=0x7fffea9dcc70, packet=std::unique_ptr<QUICPacket> containing 0x62900003fe80)
    at QUICNetVConnection.cc:1049
        error = std::unique_ptr<QUICConnectionError> containing 0x0
        has_non_probing_frame = true
        __FUNCTION__ = "_state_connection_established_process_protected_packet"
        params = {ptr = 0x0}
#19 0x0000000000d3e46f in QUICNetVConnection::_state_connection_established_receive_packet (this=0x7fffea9dcc70) at QUICNetVConnection.cc:1101
        p = std::unique_ptr<QUICPacket> containing 0x0
        error = std::unique_ptr<QUICConnectionError> containing 0x0
        result = QUICPacketCreationResult::SUCCESS
        __FUNCTION__ = "_state_connection_established_receive_packet"
#20 0x0000000000d38182 in QUICNetVConnection::state_connection_established (this=0x7fffea9dcc70, event=2500, data=0x0) at QUICNetVConnection.cc:662
        lock = {m = {m_ptr = 0x62a000015920}, locked_p = true}
        __FUNCTION__ = "state_connection_established"
        error = std::unique_ptr<QUICConnectionError> containing 0x0
---Type <return> to continue, or q <return> to quit---
#21 0x00000000006db9c8 in Continuation::handleEvent (this=0x7fffea9dcc70, event=2500, data=0x0) at /root/trafficserver/iocore/eventsystem/I_Continuation.h:165
No locals.
#22 0x0000000000d377f3 in QUICNetVConnection::state_handshake (this=0x7fffea9dcc70, event=2500, data=0x0) at QUICNetVConnection.cc:609
        packet = std::unique_ptr<QUICPacket> containing 0x0
        result = QUICPacketCreationResult::SUCCESS
        lock = {m = {m_ptr = 0x62a000015920}, locked_p = true}
        __FUNCTION__ = "state_handshake"
        error = std::unique_ptr<QUICConnectionError> containing 0x0
#23 0x00000000006db9c8 in Continuation::handleEvent (this=0x7fffea9dcc70, event=2500, data=0x0) at /root/trafficserver/iocore/eventsystem/I_Continuation.h:165
No locals.
#24 0x0000000000d3a170 in QUICNetVConnection::net_read_io (this=0x7fffea9dcc70, nh=0x7fffeed95530, lthread=0x7fffeed91800) at QUICNetVConnection.cc:817
        lock = {m = {m_ptr = 0x62a000015920}, locked_p = true}
        __FUNCTION__ = "net_read_io"
#25 0x0000000000cf95b6 in NetHandler::process_ready_list (this=0x7fffeed95530) at UnixNet.cc:396
        vc = 0x7fffea9dcc70
#26 0x0000000000cfae06 in NetHandler::waitForActivity (this=0x7fffeed95530, timeout=2283196) at UnixNet.cc:529
        epd = 0x603000019060
        lock = {m = {m_ptr = 0x62a000004d40}, locked_p = true}
        __FUNCTION__ = "waitForActivity"
        p = 0x7fffeed95650
        pd = 0x7fffeebeb800
        vc = 0x0
#27 0x0000000000dc5450 in EThread::execute_regular (this=0x7fffeed91800) at UnixEThread.cc:273
        done_one = false
        sleep_time = 2283196
        e = 0x0
        NegativeQueue = {<DLL<Event, Event::Link_link>> = {head = 0x0}, tail = 0x0}
        next_time = 1544067850903193983
        delta = 2381617
        loop_start_time = 1544067850898748559
        loop_finish_time = 1544067850898747071
        prev_metric = 0x7fffeee9b6e0
        nq_count = 3
        ev_count = 3
        METRIC_INIT = {_loop_time = {_start = 0, _min = 9223372036854775807, _max = 0}, _events = {_min = 2147483647, _max = 0, _total = 0}, _count = 0, _wait = 0}
#28 0x0000000000dc5c6f in EThread::execute (this=0x7fffeed91800) at UnixEThread.cc:326
        __FUNCTION__ = "execute"
#29 0x0000000000dc2346 in spawn_thread_internal (a=0x606000033380) at Thread.cc:92
        p = 0x606000033380
#30 0x00007ffff51066ba in start_thread (arg=0x7fffeed8e700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fffeed8e700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140737200580352, 6575282919106706231, 0, 140737488339391, 14426697, 105965433336704, -6575320000749601993, -6575269910405547209},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
---Type <return> to continue, or q <return> to quit---
#31 0x00007ffff

@maskit maskit added the QUIC label Dec 6, 2018
@maskit maskit added this to the QUIC milestone Dec 6, 2018
@maskit maskit added this to ToDo in QUIC via automation Dec 6, 2018
@maskit
Copy link
Member

maskit commented Dec 6, 2018

I guess this is just because our HQ(H3) impl is not updated.
What client did you use?

@scw00
Copy link
Member Author

scw00 commented Dec 7, 2018

See len=13744632839234567870. There is an overflow.

I use traffic_quic to download a large file(128MB).

@maskit
Copy link
Member

maskit commented Dec 7, 2018

I think traffic_quic doesn't support HQ(H3).

The current server implementation should detect HTTP version (0.9 or HQ) for interop and all requests from traffic_quic should go into the logic for 0.9 (any HQFrame should not be created). So I guess it failed to detect HTTP version and the frame parser is reading HTTP/0.9 request as HQ frames.

You can fix it if you want, but I'm not going to make the detection perfect because it will be removed in a few months.

@scw00
Copy link
Member Author

scw00 commented Dec 7, 2018

Hmm. Let's keep this issue until the detection has been removed.

@masaori335 masaori335 moved this from ToDo (Transport) to ToDo (HTTP/3) in QUIC Mar 7, 2019
@masaori335
Copy link
Contributor

Now, the detection is not used for HTTP/3. HTTP/0.9 still has the detection, but the data will be ignored when the detection failed.

24df75e

QUIC automation moved this from ToDo (HTTP/3) to Done Mar 11, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
Status: Done
QUIC
  
Done
Development

No branches or pull requests

3 participants