Assert with POST request

[shinrich]

We've just merged the 7.1.2 changes into our production build. Last night we crashed with the following stack.

#0  0x00002ab7986c2495 in raise () from /lib64/libc.so.6
#1  0x00002ab7986c3bfd in abort () from /lib64/libc.so.6
#2  0x00002ab795f7879a in ink_abort (message_format=0x2ab795f991bc "%s:%d: failed assertion `%s`") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3  0x00002ab795f758e0 in _ink_assert (expression=0x8287d2 "0", file=0x828700 "../../../../trafficserver/proxy/http/HttpTunnel.cc", line=1427)
    at ../../../../trafficserver/lib/ts/ink_assert.cc:37
#4  0x000000000066d5a6 in HttpTunnel::consumer_handler (this=0x2ab8524f4c78, event=100, c=0x2ab8524f4cb8) at ../../../../trafficserver/proxy/http/HttpTunnel.cc:1427
#5  0x000000000066dba1 in HttpTunnel::main_handler (this=0x2ab8524f4c78, event=100, data=0x2ab295e0e6a0) at ../../../../trafficserver/proxy/http/HttpTunnel.cc:1633
#6  0x000000000053c692 in Continuation::handleEvent (this=0x2ab8524f4c78, event=100, data=0x2ab295e0e6a0)
    at /var/builds/workspace/157188-v3-component/BUILD_CONTAINER/rhel6-gcc5_5/label/DOCKER-HIGH/app_root/_build/ats_build/../../trafficserver/iocore/eventsystem/I_Continuation.h:153
#7  0x00000000006760d8 in Http2Stream::update_read_request (this=0x2ab295e0e370, read_len=9223372036854775807, call_update=true)
    at ../../../../trafficserver/proxy/http2/Http2Stream.cc:495
#8  0x0000000000681827 in rcv_data_frame (cstate=..., frame=...) at ../../../../trafficserver/proxy/http2/Http2ConnectionState.cc:174
#9  0x0000000000684d61 in Http2ConnectionState::main_event_handler (this=0x2ab617f22590, event=2253, edata=0x2ab86d5e78d0)
    at ../../../../trafficserver/proxy/http2/Http2ConnectionState.cc:907
#10 0x000000000053c692 in Continuation::handleEvent (this=0x2ab617f22590, event=2253, data=0x2ab86d5e78d0)
    at /var/builds/workspace/157188-v3-component/BUILD_CONTAINER/rhel6-gcc5_5/label/DOCKER-HIGH/app_root/_build/ats_build/../../trafficserver/iocore/eventsystem/I_Continuation.h:153
#11 0x000000000067d5fd in send_connection_event (cont=0x2ab617f22590, event=2253, edata=0x2ab86d5e78d0) at ../../../../trafficserver/proxy/http2/Http2ClientSession.cc:58
#12 0x000000000067f9b9 in Http2ClientSession::do_complete_frame_read (this=0x2ab617f22330) at ../../../../trafficserver/proxy/http2/Http2ClientSession.cc:488
#13 0x000000000067fa63 in Http2ClientSession::state_process_frame_read (this=0x2ab617f22330, event=100, vio=0x2aacf0e19700, inside_frame=true)
    at ../../../../trafficserver/proxy/http2/Http2ClientSession.cc:501
#14 0x000000000067f91a in Http2ClientSession::state_complete_frame_read (this=0x2ab617f22330, event=100, edata=0x2aacf0e19700)
    at ../../../../trafficserver/proxy/http2/Http2ClientSession.cc:478
#15 0x000000000067e94f in Http2ClientSession::main_event_handler (this=0x2ab617f22330, event=100, edata=0x2aacf0e19700)
    at ../../../../trafficserver/proxy/http2/Http2ClientSession.cc:323
#16 0x000000000053c692 in Continuation::handleEvent (this=0x2ab617f22330, event=100, data=0x2aacf0e19700)
    at /var/builds/workspace/157188-v3-component/BUILD_CONTAINER/rhel6-gcc5_5/label/DOCKER-HIGH/app_root/_build/ats_build/../../trafficserver/iocore/eventsystem/I_Continuation.h:153
#17 0x00000000007c6434 in read_signal_and_update (event=100, vc=0x2aacf0e195d0) at ../../../../trafficserver/iocore/net/UnixNetVConnection.cc:144
#18 0x00000000007c93ce in UnixNetVConnection::readSignalAndUpdate (this=0x2aacf0e195d0, event=100) at ../../../../trafficserver/iocore/net/UnixNetVConnection.cc:1092
#19 0x00000000007a1594 in SSLNetVConnection::net_read_io (this=0x2aacf0e195d0, nh=0x2ab79b686c50, lthread=0x2ab79b683010)
    at ../../../../trafficserver/iocore/net/SSLNetVConnection.cc:599
#20 0x00000000007bddf5 in NetHandler::waitForActivity (this=0x2ab79b686c50, timeout=39984786) at ../../../../trafficserver/iocore/net/UnixNet.cc:497
#21 0x00000000007eaa4f in EThread::execute_regular (this=0x2ab79b683010) at ../../../../trafficserver/iocore/eventsystem/UnixEThread.cc:232
#22 0x00000000007eab25 in EThread::execute (this=0x2ab79b683010) at ../../../../trafficserver/iocore/eventsystem/UnixEThread.cc:262
#23 0x00000000007e9ab2 in spawn_thread_internal (a=0x24a1f60) at ../../../../trafficserver/iocore/eventsystem/Thread.cc:85
#24 0x00002ab798a2baa1 in start_thread () from /lib64/libpthread.so.0
#25 0x00002ab798778bcd in clone () from /lib64/libc.so.6

The immediate cause of the assert is that the H2 client sent data and the read ready was sent to a consumer because there was no producer set. The state machine is in the process of sending the request to the origin. So the ua_entry handler is set to watch_for_client_abort. The method is POST. So I assume that the client is sending post data while, we are sending the request to origin, which should be perfectly fine, and would be correctly handled in the past.

As a recall, while we are in the watch_for_client abort case, the read request is set to length 0, so no read_ready_event would be sent until the state machine had completed sending the request to origin and had set up the tunnel to send the post data to the origin.

[zwoop]

Is this still an issue, or did this get fixed?

[shinrich]

We made another build with the @duke8253's memory fixes. And it hasn't crashed yet. I think the memory fixes are already queued up for 7.1.3.

So I think we are good. I'll let this ride a few more days and close if we don't see it. But don't hold up 7.1.3 for this.

[zizhong]

@shinrich Can you please link the fix commit hash to this issue, so if someone encounters the same crash, they'll easily find the fix.

[shinrich]

Hmm. I was too hopeful. We just hit the crash again.

[shinrich]

Looking at the second core more closely, it appears that the inactivity timeout occurred on the user agent side. The current tunnel on the stack is a static tunnel. It appears that we are trying to send a message back to the user agent, even though the user agent timed out and we dutifully noted that the client aborted. We should have just cleaned up the state machine at that point. Rather it appears we let it go and the client eventually came back with a read_read which gets sent against the static error message tunnel rather than the clients post body tunnel (which was cleared at the point of the timeout).

Here is the history data.

{{fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 2}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 2}, {
    fileline = 0x81b3f0 "../../../../trafficserver/proxy/http/HttpSM.cc:676", event = 100, reentrancy = 3}, {fileline = 0x81b3f0 "../../../../trafficserver/proxy/http/HttpSM.cc:676", 
    event = 100, reentrancy = 1}, {fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 2}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 2}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 3}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 3}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 4}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 4}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 5}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 5}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 6}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 6}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 7}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 7}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 8}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 8}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 9}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 9}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 10}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 10}, {
    fileline = 0x81ee90 "../../../../trafficserver/proxy/http/HttpSM.cc:7543", event = 65535, reentrancy = 10}, {
    fileline = 0x813ad0 "../../../../trafficserver/proxy/http/HttpCacheSM.cc:118", event = 1103, reentrancy = -1}, {
    fileline = 0x81c4c0 "../../../../trafficserver/proxy/http/HttpSM.cc:2705", event = 1103, reentrancy = 11}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 12}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 12}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 13}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 13}, {
    fileline = 0x81ee20 "../../../../trafficserver/proxy/http/HttpSM.cc:7503", event = 65535, reentrancy = 13}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 14}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 14}, {
    fileline = 0x81ef00 "../../../../trafficserver/proxy/http/HttpSM.cc:7556", event = 65535, reentrancy = 14}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 15}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 15}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 16}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 16}, {
    fileline = 0x81d518 "../../../../trafficserver/proxy/http/HttpSM.cc:4683", event = 0, reentrancy = 10}, {
    fileline = 0x81bf30 "../../../../trafficserver/proxy/http/HttpSM.cc:2106", event = 103, reentrancy = 1}, {
    fileline = 0x81dcc8 "../../../../trafficserver/proxy/http/HttpSM.cc:5860", event = 65535, reentrancy = 1}, {
    fileline = 0x81cc08 "../../../../trafficserver/proxy/http/HttpSM.cc:3609", event = 105, reentrancy = 0}, {
    fileline = 0x81c600 "../../../../trafficserver/proxy/http/HttpSM.cc:2875", event = 2301, reentrancy = 1}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 2}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 2}, {
    fileline = 0x81b9f0 "../../../../trafficserver/proxy/http/HttpSM.cc:1418", event = 60000, reentrancy = 3}, {
    fileline = 0x81ba40 "../../../../trafficserver/proxy/http/HttpSM.cc:1458", event = 60000, reentrancy = 3}, {
    fileline = 0x81e1b8 "../../../../trafficserver/proxy/http/HttpSM.cc:6489", event = 65535, reentrancy = 3}, {fileline = 0x0, event = 0, reentrancy = 0} <repeats 17 times>}

Also the state machines client_request_hdr_bytes and client_response_header_bytes are non-zero. The client_response_header_bytes is kind of surprising, but perhaps that is a result of the error response setup.

[shinrich]

I think changes associated with d27be95 made it happen more frequently in build 7.1.2. But looking more closely, I think the logic that tries to send a 408 response when the client times out is fundamentally flawed. Will stare that this some more to understand the original intent of the code which has been there at least several years.

[shinrich]

Meditating on this some more on this and reviewing the definition of 408 response code (3df8e50) I guess we are intentionally sending this back to the timed out client. Need to deal with the H2 client coming back to life with data to read after we got rid of the post tunnel. I suppose we need to set up a null do_io_read on the client before setting up the static response tunnel.

[shinrich]

I think this wasn't an issue before d27be95 because the old logic wasn't using a tunnel to send the error response. So the old tunnel was around with the old vio in class the client came back to life.

The new code is clearer. I think we just need to add a null do_io_read.

I'm also a bit confused because it looks like chain_abort_all closes the VC's. Although according to the core file, the stream has not been closed.