8.0.2/8.0.3: traffic_manager[631826]: Fatal: HttpSM.cc:2516: failed assertion `magic == HTTP_SM_MAGIC_ALIVE`

[thelounge-zz]

hell, 8.0.1 broke https keep-alive and 8.0.2 has random segfaults a few times per hour

Feb 4 13:37:00 proxy traffic_server[752595]: Fatal: HttpSM.cc:2516: failed assertion magic == HTTP_SM_MAGIC_ALIVE

Feb  4 13:37:05 proxy traffic_server[752634]: NOTE: --- traffic_server Starting ---
Feb  4 13:37:05 proxy traffic_server[752634]: NOTE: traffic_server Version: Apache Traffic Server - traffic_server - 8.0.2 - (build # 020320 on Feb  3 2019 at 20:33:49)
Feb  4 13:37:05 proxy traffic_server[752634]: NOTE: RLIMIT_NOFILE(7):cur(675000),max(675000)
Feb  4 13:38:54 proxy traffic_manager[631826]: Fatal: HttpSM.cc:2516: failed assertion `magic == HTTP_SM_MAGIC_ALIVE`
Feb  4 13:38:54 proxy traffic_manager[631826]: traffic_server: received signal 6 (Aborted)
Feb  4 13:38:54 proxy traffic_manager[631826]: traffic_server - STACK TRACE:
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/bin/traffic_server(_Z19crash_logger_invokeiP9siginfo_tPv+0xa0)[0x555d1ebfa3a3]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/lib64/libpthread.so.0(+0x12080)[0x7f9a06c75080]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/lib64/libc.so.6(gsignal+0x10b)[0x7f9a068daeab]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/lib64/libc.so.6(abort+0x123)[0x7f9a068c55b9]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/lib64/trafficserver/libtscore.so.8(_Z17ink_mutex_destroyP15pthread_mutex_t+0x0)[0x7f9a091a7e7c]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/lib64/trafficserver/libtscore.so.8(ink_freelist_init_ops+0x0)[0x7f9a091a8df6]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/bin/traffic_server(_ZN6HttpSM12main_handlerEiPv+0x3b)[0x555d1ebd46d1]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/bin/traffic_server(_ZN10HttpTunnel12main_handlerEiPv+0xd6)[0x555d1eba5b54]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/bin/traffic_server(_ZN7EThread13process_eventEP5Eventi+0x91)[0x555d1eae1d9b]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/bin/traffic_server(_ZN7EThread13process_queueEP5QueueI5EventNS1_9Link_linkEEPiS5_+0x62)[0x555d1eae1e80]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/bin/traffic_server(_ZN7EThread15execute_regularEv+0x161)[0x555d1eae20cd]
Feb  4 13:38:54 proxy traffic_server[752634]: Fatal: HttpSM.cc:2516: failed assertion `magic == HTTP_SM_MAGIC_ALIVE`
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/bin/traffic_server(+0x94b56)[0x555d1eae0b56]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/lib64/libpthread.so.0(+0x7594)[0x7f9a06c6a594]
Feb  4 13:38:54 proxy traffic_manager[631826]: /usr/lib64/libc.so.6(clone+0x3f)[0x7f9a0699df4f]

[bryancall]

@thelounge-zz Did you see this issue 8.0.1? How much did you run 8.0.1?

[bryancall]

I am seeing the same issue with 8.0.3:

(gdb) bt full
#0  0x00002aaaadd121d7 in raise () from /lib64/libc.so.6
No symbol table info available.
#1  0x00002aaaadd138c8 in abort () from /lib64/libc.so.6
No symbol table info available.
#2  0x00002aaaaad29a3b in ink_abort (message_format=message_format@entry=0x2aaaaad906a7 "%s:%d: failed assertion `%s`") at ink_error.cc:99
        ap = {{gp_offset = 32, fp_offset = 48, overflow_arg_area = 0x2aaab39fe570, reg_save_area = 0x2aaab39fe4b0}}
#3  0x00002aaaaad27525 in _ink_assert (expression=expression@entry=0x735706 "magic == HTTP_SM_MAGIC_ALIVE", file=file@entry=0x7350d6 "HttpSM.cc", line=line@entry=2516) at ink_assert.cc:37
No locals.
#4  0x000000000050f767 in HttpSM::main_handler (this=<optimized out>, event=<optimized out>, data=<optimized out>) at HttpSM.cc:2516
        __FUNCTION__ = "main_handler"
#5  0x0000000000557969 in handleEvent (data=0x2aabe1f4c4f8, event=2301, this=<optimized out>) at /home/bcall/dev/yahoo/build/_build/build_debug_posix-x86_64_gcc_8/trafficserver8/iocore/eventsystem/I_Continuation.h:160
No locals.
#6  HttpTunnel::main_handler (this=0x2aabe1f4c4f8, event=<optimized out>, data=<optimized out>) at HttpTunnel.cc:1643
        p = <optimized out>
        c = <optimized out>
        sm_callback = <optimized out>
#7  0x000000000071a4b2 in handleEvent (data=0x2aac1dcbd620, event=103, this=<optimized out>) at I_Continuation.h:160

[thelounge-zz]

Did you see this issue 8.0.1?

no

How much did you run 8.0.1?

i run it all time since the "ab -c 50 -n 100000 -k" https issue don#t seem to be that relevant in real life but it's anyways bad and had to downgrade from 8.0.2 to 8.0.1 because this issue is not acceptable in production

[scw00]

Can you please print HttpSM::history ?

[bryancall]

@scw00

(gdb) frame 6
#6  HttpTunnel::main_handler (this=0x2aac4307cf58, event=<optimized out>, data=<optimized out>) at HttpTunnel.cc:1643
1643	      sm->handleEvent(HTTP_TUNNEL_EVENT_DONE, this);
(gdb) p sm->history
$6 = {history = {{location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282},
      event = 60000, reentrancy = 2}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout",
        line = 1322}, event = 60000, reentrancy = 2}, {location = {file = 0x7350d6 "HttpSM.cc",
        func = 0x738f40 <HttpSM::state_read_client_request_header(int, void*)::__FUNCTION__> "state_read_client_request_header", line = 578}, event = 100, reentrancy = 3}, {
      location = {file = 0x7350d6 "HttpSM.cc", func = 0x738f40 <HttpSM::state_read_client_request_header(int, void*)::__FUNCTION__> "state_read_client_request_header",
        line = 578}, event = 100, reentrancy = 1}, {location = {file = 0x7350d6 "HttpSM.cc",
        func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000, reentrancy = 2}, {location = {
        file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000, reentrancy = 2}, {
      location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000,
      reentrancy = 3}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322},
      event = 60000, reentrancy = 3}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback",
        line = 1282}, event = 60000, reentrancy = 4}, {location = {file = 0x7350d6 "HttpSM.cc",
        func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000, reentrancy = 4}, {location = {
        file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000, reentrancy = 5}, {
      location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000,
      reentrancy = 5}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282},
      event = 60000, reentrancy = 6}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout",
        line = 1322}, event = 60000, reentrancy = 6}, {location = {file = 0x7350d6 "HttpSM.cc",
        func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000, reentrancy = 7}, {location = {
        file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000, reentrancy = 7}, {
      location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000,
      reentrancy = 8}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322},
      event = 60000, reentrancy = 8}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback",
        line = 1282}, event = 60000, reentrancy = 9}, {location = {file = 0x7350d6 "HttpSM.cc",
        func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000, reentrancy = 9}, {location = {
        file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000, reentrancy = 10}, {
      location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000,
      reentrancy = 10}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282},
      event = 60000, reentrancy = 11}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout",
        line = 1322}, event = 60000, reentrancy = 11}, {location = {file = 0x7350d6 "HttpSM.cc",
        func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000, reentrancy = 12}, {location = {
        file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000, reentrancy = 12}, {
      location = {file = 0x7350d6 "HttpSM.cc", func = 0x738358 <HttpSM::set_next_state()::__FUNCTION__> "set_next_state", line = 7309}, event = 34463, reentrancy = 12}, {
      location = {file = 0x743cfd "HttpCacheSM.cc", func = 0x743e90 <HttpCacheSM::state_cache_open_read(int, void*)::__FUNCTION__> "state_cache_open_read", line = 116},
      event = 1102, reentrancy = -31073}, {location = {file = 0x7350d6 "HttpSM.cc",
        func = 0x738be0 <HttpSM::state_cache_open_read(int, void*)::__FUNCTION__> "state_cache_open_read", line = 2455}, event = 1102, reentrancy = 13}, {location = {
        file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000, reentrancy = 14}, {
      location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000,
      reentrancy = 14}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282},
      event = 60000, reentrancy = 15}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout",
        line = 1322}, event = 60000, reentrancy = 15}, {location = {file = 0x7350d6 "HttpSM.cc",
        func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000, reentrancy = 16}, {location = {
        file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000, reentrancy = 16}, {
      location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000,
      reentrancy = 17}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322},
      event = 60000, reentrancy = 17}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback",
        line = 1282}, event = 60000, reentrancy = 18}, {location = {file = 0x7350d6 "HttpSM.cc",
        func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000, reentrancy = 18}, {location = {
        file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000, reentrancy = 19}, {
      location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000,
      reentrancy = 19}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x7385d0 <HttpSM::setup_cache_read_transfer()::__FUNCTION__> "setup_cache_read_transfer", line = 6065},
      event = 34463, reentrancy = 19}, {location = {file = 0x7350d6 "HttpSM.cc",
        func = 0x738a60 <HttpSM::tunnel_handler_cache_read(int, HttpTunnelProducer*)::__FUNCTION__> "tunnel_handler_cache_read", line = 3299}, event = 102, reentrancy = 12}, {
      location = {file = 0x7350d6 "HttpSM.cc", func = 0x738aa0 <HttpSM::tunnel_handler_ua(int, HttpTunnelConsumer*)::__FUNCTION__> "tunnel_handler_ua", line = 3125}, event = 103,
      reentrancy = 12}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738b40 <HttpSM::tunnel_handler(int, void*)::__FUNCTION__> "tunnel_handler", line = 2810}, event = 2301,
      reentrancy = 13}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x7387f0 <HttpSM::do_cache_lookup_and_read()::__FUNCTION__> "do_cache_lookup_and_read", line = 4507},
      event = 0, reentrancy = 12}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback",
        line = 1282}, event = 60000, reentrancy = 2}, {location = {file = 0x7350d6 "HttpSM.cc",
        func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000, reentrancy = 2}, {location = {
        file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282}, event = 60000, reentrancy = 3}, {
      location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1322}, event = 60000,
      reentrancy = 3}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738dd0 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1282},
      event = 60000, reentrancy = 4}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x738db0 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout",
        line = 1322}, event = 60000, reentrancy = 4}, {location = {file = 0x7350d6 "HttpSM.cc", func = 0x7383e8 <HttpSM::kill_this()::__FUNCTION__> "kill_this", line = 6856},
      event = 34463, reentrancy = 0}, {location = {file = 0x0, func = 0x0, line = 0}, event = 0, reentrancy = 0} <repeats 12 times>}, history_pos = 53}

[oknet]

@thelounge-zz

Could you please backport PR #4379 and test again ?

[oknet]

There is an assert within HttpTunnel::main_handler:

int
HttpTunnel::main_handler(int event, void *data)
{
  HttpTunnelProducer *p = nullptr;
  HttpTunnelConsumer *c = nullptr;
  bool sm_callback      = false;

  ++reentrancy_count;

  ink_assert(sm->magic == HTTP_SM_MAGIC_ALIVE);

and HttpSM::main_handler have its own assert:

int
HttpSM::main_handler(int event, void *data)
{
  ink_release_assert(magic == HTTP_SM_MAGIC_ALIVE);

According to the backtrace:

(gdb) bt full
#0 0x00002aaaadd121d7 in raise () from /lib64/libc.so.6
No symbol table info available.
#1 0x00002aaaadd138c8 in abort () from /lib64/libc.so.6
No symbol table info available.
#2 0x00002aaaaad29a3b in ink_abort (message_format=message_format@entry=0x2aaaaad906a7 "%s:%d: failed assertion `%s`") at ink_error.cc:99
ap = {{gp_offset = 32, fp_offset = 48, overflow_arg_area = 0x2aaab39fe570, reg_save_area = 0x2aaab39fe4b0}}
#3 0x00002aaaaad27525 in _ink_assert (expression=expression@entry=0x735706 "magic == HTTP_SM_MAGIC_ALIVE", file=file@entry=0x7350d6 "HttpSM.cc", line=line@entry=2516) at ink_assert.cc:37
No locals.
#4 0x000000000050f767 in HttpSM::main_handler (this=, event=, data=) at HttpSM.cc:2516
**FUNCTION** = "main_handler"
#5 0x0000000000557969 in handleEvent (data=0x2aabe1f4c4f8, event=2301, this=) at /home/bcall/dev/yahoo/build/_build/build_debug_posix-x86_64_gcc_8/trafficserver8/iocore/eventsystem/I_Continuation.h:160
No locals.
#6 HttpTunnel::main_handler (this=0x2aabe1f4c4f8, event=, data=) at HttpTunnel.cc:1643
p = 
c = 
sm_callback = 
#7 0x000000000071a4b2 in handleEvent (data=0x2aac1dcbd620, event=103, this=) at I_Continuation.h:160

The ATS should assert at frame 6th if debug enabled.

@bryancall Do you have debug enabled ?

[thelounge-zz]

@oknet no i can't backport anything, i work with tarballs and rpmbuild and have no business in C/C++ at all

[bryancall]

@oknet I am not running a debug build or else it would have asserted in the tunnel. It looks like the HttpSM has been killed and there are still some events happening in the tunnel.

[bryancall]

@oknet I will try a test with #4379 and see what happens. This bug is very reproducible with me and happens within the first 1000 requests of the server starting.