Assertion in HttpCacheSM::state_cache_open_read

[zwoop]

Not sure how long this has been going on for, but today I made a new (debug) build on Docs, without ASAN, to try to get a better trace for the Brotli crasher. However, very frequently, we now assert as below :-/.

#0  0x00002b4bcad4f337 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:55
#1  0x00002b4bcad50a28 in __GI_abort () at abort.c:90
#2  0x00002b4bc875b7d1 in ink_abort (message_format=0x2b4bc87c90e8 "%s:%d: failed assertion `%s`") at ink_error.cc:99
#3  0x00002b4bc875880e in _ink_assert (expression=0x985424 "captive_action.cancelled == 0", file=0x985398 "HttpCacheSM.cc", line=101) at ink_assert.cc:37
#4  0x00000000007423af in HttpCacheSM::state_cache_open_read (this=0x2b4bd0970da8, event=1103, data=0xffffffffffffb049) at HttpCacheSM.cc:101
#5  0x000000000064a6b3 in Continuation::handleEvent (this=0x2b4bd0970da8, event=1103, data=0xffffffffffffb049) at /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
#6  0x000000000086a7d9 in Cache::open_read (this=0x0, cont=0x2b4bd0970da8, key=0x2b4bd0970e80, request=0x2b4bd096f730, params=0x2b4bd096fcb0, type=CACHE_FRAG_TYPE_HTTP, hostname=0x2b4bd097402b "docs.trafficserver.apache.org", host_len=29) at CacheRead.cc:100
#7  0x000000000085101f in CacheProcessor::open_read (this=0xe49cc0 <cacheProcessor>, cont=0x2b4bd0970da8, key=0x2b4bd0970e70, request=0x2b4bd096f730, params=0x2b4bd096fcb0, pin_in_cache=0, type=CACHE_FRAG_TYPE_HTTP) at Cache.cc:3153
#8  0x0000000000742f37 in HttpCacheSM::do_cache_open_read (this=0x2b4bd0970da8, key=...) at HttpCacheSM.cc:271
#9  0x00000000007430c3 in HttpCacheSM::open_read (this=0x2b4bd0970da8, key=0x2b4bcf800670, url=0x2b4bd096f0b8, hdr=0x2b4bd096f730, params=0x2b4bd096fcb0, pin_in_cache=0) at HttpCacheSM.cc:304
#10 0x00000000006e4294 in HttpSM::do_cache_lookup_and_read (this=0x2b4bd096f000) at HttpSM.cc:4516
#11 0x00000000006efe7e in HttpSM::set_next_state (this=0x2b4bd096f000) at HttpSM.cc:7333
#12 0x00000000006ef15c in HttpSM::call_transact_and_set_next_state (this=0x2b4bd096f000, f=0x0) at HttpSM.cc:7163
#13 0x00000000006dbb05 in HttpSM::state_cache_open_write (this=0x2b4bd096f000, event=1102, data=0x2b4bccfff880) at HttpSM.cc:2482
#14 0x00000000006dc55c in HttpSM::main_handler (this=0x2b4bd096f000, event=1102, data=0x2b4bccfff880) at HttpSM.cc:2595
#15 0x000000000064a6b3 in Continuation::handleEvent (this=0x2b4bd096f000, event=1102, data=0x2b4bccfff880) at /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
#16 0x0000000000742c2f in HttpCacheSM::state_cache_open_write (this=0x2b4bd0970da8, event=2, data=0x2b4bccfff880) at HttpCacheSM.cc:221
#17 0x000000000064a6b3 in Continuation::handleEvent (this=0x2b4bd0970da8, event=2, data=0x2b4bccfff880) at /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
#18 0x0000000000946b2b in EThread::process_event (this=0x2b4bcd220000, e=0x2b4bccfff880, calling_code=2) at UnixEThread.cc:143
#19 0x0000000000947106 in EThread::execute_regular (this=0x2b4bcd220000) at UnixEThread.cc:256
#20 0x000000000094745f in EThread::execute (this=0x2b4bcd220000) at UnixEThread.cc:351
#21 0x0000000000945da5 in spawn_thread_internal (a=0x2b4bcc2cfb40) at Thread.cc:92
#22 0x00002b4bca0e1e65 in start_thread (arg=0x2b4bcf801700) at pthread_create.c:307
#23 0x00002b4bcae1788d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

bt full is

#0  0x00002b4bcad4f337 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:55
        resultvar = 0
        pid = 3788
        selftid = 3797
#1  0x00002b4bcad50a28 in __GI_abort () at abort.c:90
        save_stage = 2
        act = {
          __sigaction_handler = {
            sa_handler = 0x0,
            sa_sigaction = 0x0
          },
          sa_mask = {
            __val = {0 <repeats 16 times>}
          },
          sa_flags = 0,
          sa_restorer = 0x2b4bd0970528
        }
        sigs = {
          __val = {32, 0 <repeats 15 times>}
        }
#2  0x00002b4bc875b7d1 in ink_abort (message_format=0x2b4bc87c90e8 "%s:%d: failed assertion `%s`") at ink_error.cc:99
        ap = {{
            gp_offset = 32,
            fp_offset = 48,
            overflow_arg_area = 0x2b4bcf800350,
            reg_save_area = 0x2b4bcf800290
          }}
#3  0x00002b4bc875880e in _ink_assert (expression=0x985424 "captive_action.cancelled == 0", file=0x985398 "HttpCacheSM.cc", line=101) at ink_assert.cc:37
No locals.
#4  0x00000000007423af in HttpCacheSM::state_cache_open_read (this=0x2b4bd0970da8, event=1103, data=0xffffffffffffb049) at HttpCacheSM.cc:101
        __FUNCTION__ = "state_cache_open_read"
#5  0x000000000064a6b3 in Continuation::handleEvent (this=0x2b4bd0970da8, event=1103, data=0xffffffffffffb049) at /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
No locals.
#6  0x000000000086a7d9 in Cache::open_read (this=0x0, cont=0x2b4bd0970da8, key=0x2b4bd0970e80, request=0x2b4bd096f730, params=0x2b4bd096fcb0, type=CACHE_FRAG_TYPE_HTTP, hostname=0x2b4bd097402b "docs.trafficserver.apache.org", host_len=29) at CacheRead.cc:100
        vol = 0x0
        result = {
          w = {0, 0, 0, 0, 0}
        }
        last_collision = 0x22e168c9c06ca1c6
        mutex = 0x0
        od = 0x2b4b00000000
        c = 0x0
        __FUNCTION__ = "open_read"
#7  0x000000000085101f in CacheProcessor::open_read (this=0xe49cc0 <cacheProcessor>, cont=0x2b4bd0970da8, key=0x2b4bd0970e70, request=0x2b4bd096f730, params=0x2b4bd096fcb0, pin_in_cache=0, type=CACHE_FRAG_TYPE_HTTP) at Cache.cc:3153
No locals.
#8  0x0000000000742f37 in HttpCacheSM::do_cache_open_read (this=0x2b4bd0970da8, key=...) at HttpCacheSM.cc:271
        action_handle = 0x2b4bd0970e70
#9  0x00000000007430c3 in HttpCacheSM::open_read (this=0x2b4bd0970da8, key=0x2b4bcf800670, url=0x2b4bd096f0b8, hdr=0x2b4bd096f730, params=0x2b4bd096fcb0, pin_in_cache=0) at HttpCacheSM.cc:304
        act_return = 0x2b4bcf800670
#10 0x00000000006e4294 in HttpSM::do_cache_lookup_and_read (this=0x2b4bd096f000) at HttpSM.cc:4516
        c_url = 0x2b4bd096f0b8
        __FUNCTION__ = "do_cache_lookup_and_read"
        key = {
          hostlen = 29,
          hostname = 0x2b4bd097402b "docs.trafficserver.apache.org",
          hash = {
            b = {24118497333652305, 2513405282775507398},
            u64 = {24118497333652305, 2513405282775507398},
            u32 = {1108781905, 5615525, 3228344774, 585197769},
            u8 = "Q\253\026B\245\257U\000ơl\300\311h\341\""
          },
          hash2 = {
            b = {0, 0},
            u64 = {0, 0},
            u32 = {0, 0, 0, 0},
            u8 = '\000' <repeats 15 times>
          }
        }
        cache_action_handle = 0x2b4bcf8006f0
#11 0x00000000006efe7e in HttpSM::set_next_state (this=0x2b4bd096f000) at HttpSM.cc:7333
        __FUNCTION__ = "set_next_state"
#12 0x00000000006ef15c in HttpSM::call_transact_and_set_next_state (this=0x2b4bd096f000, f=0x0) at HttpSM.cc:7163
        __FUNCTION__ = "call_transact_and_set_next_state"
#13 0x00000000006dbb05 in HttpSM::state_cache_open_write (this=0x2b4bd096f000, event=1102, data=0x2b4bccfff880) at HttpSM.cc:2482
        __FUNCTION__ = "state_cache_open_write"
#14 0x00000000006dc55c in HttpSM::main_handler (this=0x2b4bd096f000, event=1102, data=0x2b4bccfff880) at HttpSM.cc:2595
        jump_point = NULL
        __FUNCTION__ = "main_handler"
        vc_entry = 0x0
#15 0x000000000064a6b3 in Continuation::handleEvent (this=0x2b4bd096f000, event=1102, data=0x2b4bccfff880) at /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
No locals.
#16 0x0000000000742c2f in HttpCacheSM::state_cache_open_write (this=0x2b4bd0970da8, event=2, data=0x2b4bccfff880) at HttpCacheSM.cc:221
        __FUNCTION__ = "state_cache_open_write"
        read_retry_on_write_fail = false
#17 0x000000000064a6b3 in Continuation::handleEvent (this=0x2b4bd0970da8, event=2, data=0x2b4bccfff880) at /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
No locals.
#18 0x0000000000946b2b in EThread::process_event (this=0x2b4bcd220000, e=0x2b4bccfff880, calling_code=2) at UnixEThread.cc:143
        c_temp = 0x2b4bd0970da8
        lock = {
          m = {
            m_ptr = 0x2b4bd08b3160
          },
          lock_acquired = true
        }
        __FUNCTION__ = "process_event"
#19 0x0000000000947106 in EThread::execute_regular (this=0x2b4bcd220000) at UnixEThread.cc:256
        done_one = true
        sleep_time = 60000000
        e = 0x2b4bccfff880
        NegativeQueue = {
          <DLL<Event, Event::Link_link>> = {
            head = 0x0
          },
          members of Queue<Event, Event::Link_link>:
          tail = 0x0
        }
        next_time = 1582043570761776255
        delta = 60331370
        loop_start_time = 1582043570182109899
        loop_finish_time = 1582043570182107625
        prev_metric = 0x2b4bcd325e60
        nq_count = 1
        ev_count = 1
        METRIC_INIT = {
          _loop_time = {
            _start = 0,
            _min = 9223372036854775807,
            _max = 0
          },
          _events = {
            _min = 2147483647,
            _max = 0,
            _total = 0
          },
          _count = 0,
          _wait = 0
        }
#20 0x000000000094745f in EThread::execute (this=0x2b4bcd220000) at UnixEThread.cc:351
        __FUNCTION__ = "execute"
#21 0x0000000000945da5 in spawn_thread_internal (a=0x2b4bcc2cfb40) at Thread.cc:92
        p = 0x2b4bcc2cfb40
#22 0x00002b4bca0e1e65 in start_thread (arg=0x2b4bcf801700) at pthread_create.c:307
        __res = <optimized out>
        pd = 0x2b4bcf801700
        now = <optimized out>
        unwind_buf = {
          cancel_jmp_buf = {{
              jmp_buf = {47604603819776, -819238072451363906, 0, 2101248, 0, 47604603819776, -6757963157159834690, -6757951079157756994},
              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>
#23 0x00002b4bcae1788d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

HttpSM history:

(gdb) frame 10
#10 0x00000000006e4294 in HttpSM::do_cache_lookup_and_read (this=0x2b4bd096f000) at HttpSM.cc:4516
4516	    static_cast<time_t>((t_state.cache_control.pin_in_cache_for < 0) ? 0 : t_state.cache_control.pin_in_cache_for));
(gdb) print history
$1 = {
  history = {{
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x974d00 <HttpSM::state_read_client_request_header(int, void*)::__FUNCTION__> "state_read_client_request_header",
        line = 601
      },
      event = 100,
      reentrancy = 2
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x974e70 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback",
        line = 1325
      },
      event = 60000,
      reentrancy = 3
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x974e90 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout",
        line = 1365
      },
      event = 60000,
      reentrancy = 3
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x974e70 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback",
        line = 1325
      },
      event = 60000,
      reentrancy = 4
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x974e90 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout",
        line = 1365
      },
      event = 60000,
      reentrancy = 4
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x974e70 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback",
        line = 1325
      },
      event = 60000,
      reentrancy = 5
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x974e90 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout",
        line = 1365
      },
      event = 60000,
      reentrancy = 5
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x975908 <HttpSM::set_next_state()::__FUNCTION__> "set_next_state",
        line = 7332
      },
      event = 34463,
      reentrancy = 5
    }, {
      location = {
        file = 0x985398 "HttpCacheSM.cc",
        func = 0x985a60 <HttpCacheSM::state_cache_open_read(int, void*)::__FUNCTION__> "state_cache_open_read",
        line = 100
      },
      event = 1103,
      reentrancy = -31073
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x975090 <HttpSM::state_cache_open_read(int, void*)::__FUNCTION__> "state_cache_open_read",
        line = 2506
      },
      event = 1103,
      reentrancy = 6
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x974e70 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback",
        line = 1325
      },
      event = 60000,
      reentrancy = 7
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x974e90 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout",
        line = 1365
      },
      event = 60000,
      reentrancy = 7
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x975908 <HttpSM::set_next_state()::__FUNCTION__> "set_next_state",
        line = 7292
      },
      event = 34463,
      reentrancy = 7
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x975460 <HttpSM::do_cache_lookup_and_read()::__FUNCTION__> "do_cache_lookup_and_read",
        line = 4527
      },
      event = 59464,
      reentrancy = 5
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x974ff0 <HttpSM::state_hostdb_lookup(int, void*)::__FUNCTION__> "state_hostdb_lookup",
        line = 2227
      },
      event = 500,
      reentrancy = 1
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x975908 <HttpSM::set_next_state()::__FUNCTION__> "set_next_state",
        line = 7441
      },
      event = 34463,
      reentrancy = 1
    }, {
      location = {
        file = 0x985398 "HttpCacheSM.cc",
        func = 0x985a80 <HttpCacheSM::state_cache_open_write(int, void*)::__FUNCTION__> "state_cache_open_write",
        line = 160
      },
      event = 1109,
      reentrancy = -31073
    }, {
      location = {
        file = 0x985398 "HttpCacheSM.cc",
        func = 0x985a80 <HttpCacheSM::state_cache_open_write(int, void*)::__FUNCTION__> "state_cache_open_write",
        line = 160
      },
      event = 2,
      reentrancy = -31073
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x975070 <HttpSM::state_cache_open_write(int, void*)::__FUNCTION__> "state_cache_open_write",
        line = 2388
      },
      event = 1102,
      reentrancy = 1
    }, {
      location = {
        file = 0x9701d6 "HttpSM.cc",
        func = 0x975908 <HttpSM::set_next_state()::__FUNCTION__> "set_next_state",
        line = 7332
      },
      event = 34463,
      reentrancy = 1
    }, {
      location = {
        file = 0x985398 "HttpCacheSM.cc",
        func = 0x985a60 <HttpCacheSM::state_cache_open_read(int, void*)::__FUNCTION__> "state_cache_open_read",
        line = 100
      },
      event = 1103,
      reentrancy = -31073
    }, {
      location = {
        file = 0x0,
        func = 0x0,
        line = 0
      },
      event = 0,
      reentrancy = 0
    } <repeats 44 times>},
  history_pos = 21
}

[zwoop]

This is running with current 9.0.x branch, commit ID a709cf1, and #6407 PR applied.

[zwoop]

I'm trying now without #6407 to see if it's causing this assertion.

[shinrich]

That is a very odd history. It is like the caching logic is being intermingled with the DNS lookup logic.

[zwoop]

@sudheerv and @ezelkow1 suggests this assertion is due to fail_action=5, and turning that off confirms. However, then I get another segfault (filing separate issue).

[zwoop]

Looks like #6431 eliminates this assert. But, now we're getting a new one, will file another Issue...