Assertion in H2, from pending_action != nullptr

[dmorilha]

running debug version of 7.1.4 with asan, no freelist in gdb

Fatal: /opt/src/trafficserver/proxy/http/HttpSM.cc:6827: failed assertion `pending_action == nullptr`

Thread 6 "[ET_NET 3]" received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffeca4e700 (LWP 30291)]
0x00007ffff493d428 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.
#0  0x00007ffff493d428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#1  0x00007ffff493f02a in __GI_abort () at abort.c:89
#2  0x00007ffff6bb376c in ink_abort (message_format=0x7ffff6be9960 "%s:%d: failed assertion `%s`") at /opt/src/trafficserver/lib/ts/ink_error.cc:99
#3  0x00007ffff6babcb1 in _ink_assert (expression=0xc3ae00 "pending_action == nullptr", file=0xc39380 "/opt/src/trafficserver/proxy/http/HttpSM.cc", line=6827) at /opt/src/trafficserver/lib/t
s/ink_assert.cc:37
#4  0x000000000071f1cd in HttpSM::kill_this (this=0x62400068c100) at /opt/src/trafficserver/proxy/http/HttpSM.cc:6827
#5  0x00000000006f17a2 in HttpSM::main_handler (this=0x62400068c100, event=104, data=0x61900082f7d0) at /opt/src/trafficserver/proxy/http/HttpSM.cc:2640
#6  0x000000000055f411 in Continuation::handleEvent (this=0x62400068c100, event=104, data=0x61900082f7d0) at /opt/src/trafficserver/iocore/eventsystem/I_Continuation.h:152
#7  0x00000000007f97c0 in Http2Stream::main_event_handler (this=0x61900082f580, event=104, edata=0x6090000f6740) at /opt/src/trafficserver/proxy/http2/Http2Stream.cc:122
#8  0x000000000055f411 in Continuation::handleEvent (this=0x61900082f580, event=104, data=0x6090000f6740) at /opt/src/trafficserver/iocore/eventsystem/I_Continuation.h:152
#9  0x0000000000bab0e3 in EThread::process_event (this=0x7fffed269800, e=0x6090000f6740, calling_code=104) at /opt/src/trafficserver/iocore/eventsystem/UnixEThread.cc:140
#10 0x0000000000bab631 in EThread::process_queue (this=0x7fffed269800, NegativeQueue=0x7fffeca4dd10) at /opt/src/trafficserver/iocore/eventsystem/UnixEThread.cc:175
#11 0x0000000000bab8eb in EThread::execute_regular (this=0x7fffed269800) at /opt/src/trafficserver/iocore/eventsystem/UnixEThread.cc:207
#12 0x0000000000bac261 in EThread::execute (this=0x7fffed269800) at /opt/src/trafficserver/iocore/eventsystem/UnixEThread.cc:278
#13 0x0000000000ba97e3 in spawn_thread_internal (a=0x604000018d90) at /opt/src/trafficserver/iocore/eventsystem/Thread.cc:84
#14 0x00007ffff578a6ba in start_thread (arg=0x7fffeca4e700) at pthread_create.c:333
#15 0x00007ffff4a0f41d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

[dmorilha]

(gdb) list
6822        // get killed.
6823        if (callout_state == HTTP_API_NO_CALLOUT && pending_action) {
6824          pending_action->cancel();
6825          pending_action = nullptr;
6826        } else if (pending_action) {
6827          ink_assert(pending_action == nullptr);
6828        }
6829
6830        cache_sm.end_both();
6831        if (second_cache_sm) {
(gdb) print callout_state
$3 = HTTP_API_IN_CALLOUT
(gdb) print *pending_action
$4 = {_vptr.Action = 0xd75198 <vtable for Event+16>, continuation = 0x624000a1e100, mutex = {m_ptr = 0x60c0005ff140}, cancelled = 0}
(gdb) print pending_action->continuation
$5 = (Continuation *) 0x624000a1e100
(gdb) print *pending_action->continuation
$6 = {<force_VFPT_to_top> = {_vptr.force_VFPT_to_top = 0xc48608 <vtable for HttpSM+16>}, handler = (int (Continuation::*)(Continuation * const, int, 
    void *)) 0x6f0eb4 <HttpSM::main_handler(int, void*)>, handler_name = 0xc39540 "&HttpSM::main_handler", mutex = {m_ptr = 0x60c0005ff140}, link = {<SLink<Continuation>> = {next = 0x0}, 
    prev = 0x0}, control_flags = {raw_flags = 0}}
(gdb) print pending_action->mutex
$7 = {m_ptr = 0x60c0005ff140}
(gdb) print *pending_action->mutex.m_ptr
$9 = {<RefCountObj> = {<ForceVFPTToTop> = {_vptr.ForceVFPTToTop = 0xbb3a80 <vtable for ProxyMutex+16>}, m_refcount = 11}, the_mutex = {__data = {__lock = 1, __count = 0, __owner = 24521, 
      __nusers = 1, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = "\001\000\000\000\000\000\000\000\311_\000\000\001", '\000' <repeats 26 times>, 
    __align = 1}, thread_holding = 0x7fffed36c800, nthread_holding = 3, hold_time = 1534438575540844183, srcloc = {
    file = 0xd9a1e0 "/opt/src/trafficserver/iocore/eventsystem/UnixEThread.cc", func = 0xd9a720 <EThread::process_event(Event*, int)::__FUNCTION__> "process_event", line = 130}, 
  handler = 0x0}

[dmorilha]

this patch is looking very very promising to fix this and H2 server push issue:

$ git diff HEAD^
diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc
index e9e70cda4..11c661536 100644
--- a/proxy/http/HttpSM.cc
+++ b/proxy/http/HttpSM.cc
@@ -6820,7 +6820,9 @@ HttpSM::kill_this()
     // state. This is because we are depending on the
     // callout to complete for the state machine to
     // get killed.
-    if (callout_state == HTTP_API_NO_CALLOUT && pending_action) {
+    if ((callout_state == HTTP_API_NO_CALLOUT
+          || callout_state == HTTP_API_IN_CALLOUT)
+        && pending_action) {
       pending_action->cancel();
       pending_action = nullptr;
     } else if (pending_action) {

[maskit]

I'm not so familiar with these states. @shinrich Can you take a look?

[shinrich]

Sure, I'll look into this. It looks like the original assert is trying to catch out the case where there is a pending action left over but we are in the midst of the hooks. Will poke around a bit.

[maskit]

I was able to reproduce (probably) the same abort on my local box. Only I had to do was run this script:

#!/bin/bash
cmd="h2load -n 1000 -c 100 https://localhost:8443/"
$cmd &
$cmd &
$cmd &
$cmd &
$cmd &
$cmd &
$cmd &
$cmd &
$cmd &
$cmd &

The patch @dmorilha provided works, but I'm not sure this is a right way to fix it. The comment above the block says:

////////////////////////////////
// cancel uncompleted actions //
////////////////////////////////
// The action should be cancelled only if
// the state machine is in HTTP_API_NO_CALLOUT
// state. This is because we are depending on the
// callout to complete for the state machine to
// get killed.

and another place that sets pending_action says:

trafficserver/proxy/http/HttpSM.cc

Lines 1446 to 1454 in 2a9f0f9

	if (!plugin_lock) {
	api_timer = -Thread::get_hrtime_updated();
	HTTP_SM_SET_DEFAULT_HANDLER(&HttpSM::state_api_callout);
	ink_assert(pending_action == nullptr);
	pending_action = mutex->thread_holding->schedule_in(this, HRTIME_MSECONDS(10));
	// Should @a callout_state be reset back to HTTP_API_NO_CALLOUT here? Because the default
	// handler has been changed the value isn't important to the rest of the state machine
	// but not resetting means there is no way to reliably detect re-entrance to this state with an
	// outstanding callout.

I have no idea how we can fix it.

[shinrich]

Despite the comment, I think we do have to cancel all the pending actions at this point. If we have a non-null pending action while we are in the CALLOUT state, there still is a hook in progress. At this point in kill_this, the key data structures will be destroyed making any outstanding pending action a future time crash bomb.

But then that begs the question of why we are killing a transaction with an outstanding hook.

[zwoop]

I'm getting this assertion now on Docs (running v9.0.x), I filed (and closed) #6443 which has pretty much the same stack trace as far as I can tell.

[shinrich]

Has #6364 been cherry-picked back to 9.0.x yet? @a-canary found that we weren't doing a very good job waiting for the session/transaction open/close hooks to finish. If we weren't waiting and hit a delay it might triggered the assert in kill_this.

Although, what kind of plugins are your running on the docs machine?

[zwoop]

Docs is running with header_rewrite, compress and Lua plugin I think.

[shinrich]

Looks like #6364 has been cherry-picked to 9.0.x. @calavera are you guys still seeing this issue?