Assertion in HttpCacheSM captive_action.cancelled == 0

[maskit]

I realized that an assertion below fails on my laptop while I was running h2spec. Reverting #7667 solves the issue, but I'm not sure how it is related.

Fatal: HttpCacheSM.cc:161: failed assertion `captive_action.cancelled == 0`
2021-04-13 11:33:40.743573+0900 traffic_server[76017:10095094] Fatal: HttpCacheSM.cc:161: failed assertion `captive_action.cancelled == 0`
Process 76017 stopped
* thread #3, name = '[ET_NET 1]', stop reason = signal SIGABRT
    frame #0: 0x00007fff2037a462 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff2037a462 <+10>: jae    0x7fff2037a46c            ; <+20>
    0x7fff2037a464 <+12>: movq   %rax, %rdi
    0x7fff2037a467 <+15>: jmp    0x7fff203746a1            ; cerror_nocancel
    0x7fff2037a46c <+20>: retq   
Target 0: (traffic_server) stopped.
(lldb) bt
* thread #3, name = '[ET_NET 1]', stop reason = signal SIGABRT
  * frame #0: 0x00007fff2037a462 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff203a8610 libsystem_pthread.dylib`pthread_kill + 263
    frame #2: 0x00007fff202fb720 libsystem_c.dylib`abort + 120
    frame #3: 0x0000000103a2ac8a libtscore.10.dylib`ink_abort(message_format="%s:%d: failed assertion `%s`") at ink_error.cc:99:3
    frame #4: 0x0000000103a20727 libtscore.10.dylib`::_ink_assert(expression="captive_action.cancelled == 0", file="HttpCacheSM.cc", line=161) at ink_assert.cc:37:3
    frame #5: 0x00000001001f58e9 traffic_server`HttpCacheSM::state_cache_open_write(this=0x0000000110ea2c30, event=1109, data=0xffffffffffffb04f) at HttpCacheSM.cc:161:3
    frame #6: 0x000000010000aab5 traffic_server`Continuation::handleEvent(this=0x0000000110ea2c30, event=1109, data=0xffffffffffffb04f) at I_Continuation.h:219:12
    frame #7: 0x0000000100b1b78c traffic_server`Cache::open_write(this=0x00006040001cbf10, cont=0x0000000110ea2c30, key=0x000000010a3ccd90, info=0x0000000000000000, apin_in_cache=0, (null)=0x0000000000000000, type=CACHE_FRAG_TYPE_HTTP, hostname="127.0.0.112345http127.0.0.1:12345http://127.0.0.1:12345/", host_len=9) at CacheWrite.cc:1859:9
    frame #8: 0x0000000100a07f34 traffic_server`CacheProcessor::open_write(this=0x0000000101b138a0, cont=0x0000000110ea2c30, expected_size=0, key=0x000000010a3ccd80, request=0x0000000110ea1630, old_info=0x0000000000000000, pin_in_cache=0, type=CACHE_FRAG_TYPE_HTTP) at Cache.cc:3254:24
    frame #9: 0x00000001001f8373 traffic_server`HttpCacheSM::open_write(this=0x0000000110ea2c30, key=0x000000010a3ccd80, url=0x0000000110ea1648, request=0x0000000110ea1630, old_info=0x0000000000000000, pin_in_cache=0, retry=true, allow_multiple=false) at HttpCacheSM.cc:363:20
    frame #10: 0x000000010034edd6 traffic_server`HttpSM::do_cache_prepare_action(this=0x0000000110ea0e80, c_sm=0x0000000110ea2c30, object_read_info=0x0000000000000000, retry=true, allow_multiple=false) at HttpSM.cc:4783:11
    frame #11: 0x000000010036202c traffic_server`HttpSM::do_cache_prepare_write(this=0x0000000110ea0e80) at HttpSM.cc:4712:3
    frame #12: 0x0000000100360b9e traffic_server`HttpSM::set_next_state(this=0x0000000110ea0e80) at HttpSM.cc:7625:5
    frame #13: 0x00000001002e7ff3 traffic_server`HttpSM::call_transact_and_set_next_state(this=0x0000000110ea0e80, f=0x0000000000000000)(HttpTransact::State*)) at HttpSM.cc:7350:3
    frame #14: 0x00000001003017c6 traffic_server`HttpSM::handle_api_return(this=0x0000000110ea0e80) at HttpSM.cc:1686:5
    frame #15: 0x00000001002ff0da traffic_server`HttpSM::state_api_callout(this=0x0000000110ea0e80, event=0, data=0x0000000000000000) at HttpSM.cc:1618:5
    frame #16: 0x0000000100352683 traffic_server`HttpSM::do_api_callout_internal(this=0x0000000110ea0e80) at HttpSM.cc:5292:10
    frame #17: 0x00000001002dbc3d traffic_server`HttpSM::do_api_callout(this=0x0000000110ea0e80) at HttpSM.cc:434:12
    frame #18: 0x000000010035d0bc traffic_server`HttpSM::set_next_state(this=0x0000000110ea0e80) at HttpSM.cc:7384:5
    frame #19: 0x00000001002e7ff3 traffic_server`HttpSM::call_transact_and_set_next_state(this=0x0000000110ea0e80, f=0x0000000000000000)(HttpTransact::State*)) at HttpSM.cc:7350:3
    frame #20: 0x000000010035dda1 traffic_server`HttpSM::set_next_state(this=0x0000000110ea0e80) at HttpSM.cc:7429:7
    frame #21: 0x00000001002e7ff3 traffic_server`HttpSM::call_transact_and_set_next_state(this=0x0000000110ea0e80, f=0x0000000000000000)(HttpTransact::State*)) at HttpSM.cc:7350:3
    frame #22: 0x00000001003017c6 traffic_server`HttpSM::handle_api_return(this=0x0000000110ea0e80) at HttpSM.cc:1686:5
    frame #23: 0x00000001002ff0da traffic_server`HttpSM::state_api_callout(this=0x0000000110ea0e80, event=0, data=0x0000000000000000) at HttpSM.cc:1618:5
    frame #24: 0x0000000100352683 traffic_server`HttpSM::do_api_callout_internal(this=0x0000000110ea0e80) at HttpSM.cc:5292:10
    frame #25: 0x00000001002dbc3d traffic_server`HttpSM::do_api_callout(this=0x0000000110ea0e80) at HttpSM.cc:434:12
    frame #26: 0x000000010032b887 traffic_server`HttpSM::setup_cache_lookup_complete_api(this=0x0000000110ea0e80) at HttpSM.cc:2585:3
    frame #27: 0x000000010032b6d5 traffic_server`HttpSM::state_cache_open_read(this=0x0000000110ea0e80, event=1103, data=0xffffffffffffb04f) at HttpSM.cc:2647:5
    frame #28: 0x00000001002da869 traffic_server`HttpSM::main_handler(this=0x0000000110ea0e80, event=1103, data=0xffffffffffffb04f) at HttpSM.cc:2689:5
    frame #29: 0x000000010000aab5 traffic_server`Continuation::handleEvent(this=0x0000000110ea0e80, event=1103, data=0xffffffffffffb04f) at I_Continuation.h:219:12
    frame #30: 0x00000001001f455b traffic_server`HttpCacheSM::state_cache_open_read(this=0x0000000110ea2c30, event=1103, data=0xffffffffffffb04f) at HttpCacheSM.cc:128:20
    frame #31: 0x000000010000aab5 traffic_server`Continuation::handleEvent(this=0x0000000110ea2c30, event=1103, data=0xffffffffffffb04f) at I_Continuation.h:219:12
    frame #32: 0x0000000100abaf4c traffic_server`CacheVC::openReadFromWriterFailure(this=0x0000000110eccb60, event=1103, e=0xffffffffffffb04f) at CacheRead.cc:189:25
    frame #33: 0x0000000100ab395d traffic_server`CacheVC::openReadFromWriter(this=0x0000000110eccb60, event=2, e=0x000062c000005140) at CacheRead.cc:348:16
    frame #34: 0x000000010000aab5 traffic_server`Continuation::handleEvent(this=0x0000000110eccb60, event=2, data=0x000062c000005140) at I_Continuation.h:219:12
    frame #35: 0x0000000101019454 traffic_server`EThread::process_event(this=0x0000000109e14800, e=0x000062c000005140, calling_code=2) at UnixEThread.cc:164:22
    frame #36: 0x000000010101ae4a traffic_server`EThread::execute_regular(this=0x0000000109e14800) at UnixEThread.cc:273:11
    frame #37: 0x000000010101c553 traffic_server`EThread::execute(this=0x0000000109e14800) at UnixEThread.cc:364:11
    frame #38: 0x0000000101016a5b traffic_server`spawn_thread_internal(a=0x0000607000007fe0) at Thread.cc:92:12
    frame #39: 0x00007fff203a8950 libsystem_pthread.dylib`_pthread_start + 224
    frame #40: 0x00007fff203a447b libsystem_pthread.dylib`thread_start + 15

[shinrich]

Looks like the new PendingClass will cancel an action before setting it to nulllptr (clearing it). Should be harmless for an action that has already executed (as it has on this stack frame 31/32).

PendingAction &
  operator=(Action *b)
  {
    // Don't do anything if the new action is _DONE
    if (b != ACTION_RESULT_DONE) {
      if (b != pending_action && pending_action != nullptr) {
        pending_action->cancel();
      }
      pending_action = b;
    }
    return *this;
  }

[cukiernik]

Still at the commit 99efb64.
The latest commit without this fail is a8b6746