ATS crashes in ProxyClientSession.cc

[jsnjack]

Hi,

We have a problem running the latest ATS version. It crashes around 20 times per day with the following stack trace (I have also attached an extended log file
ats7.txt ):

Fatal: ProxyClientSession.cc:165: failed assertion `false`
traffic_server: using root directory '/opt/ts'
traffic_server: received signal 6 (Aborted)
traffic_server - STACK TRACE: 
/opt/ts/bin/traffic_server(_Z19crash_logger_invokeiP9siginfo_tPv+0x8e)[0x4b4dae]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf890)[0x2b828f6c4890]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x2b829032d067]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x2b829032e448]
/opt/ts/lib/libtsutil.so.7(+0x2f3bb)[0x2b828df2b3bb]
/opt/ts/lib/libtsutil.so.7(+0x2d035)[0x2b828df29035]
/opt/ts/bin/traffic_server(_ZN18ProxyClientSession17state_api_calloutEiPv+0x16c)[0x50b1bc]
/opt/ts/bin/traffic_server(_ZN18UnixNetVConnection9mainEventEiP5Event+0x650)[0x788040]
/opt/ts/bin/traffic_server(_ZN13InactivityCop16check_inactivityEiP5Event+0x1e3)[0x77f4f3]
/opt/ts/bin/traffic_server(_ZN7EThread13process_eventEP5Eventi+0x120)[0x7c2600]
/opt/ts/bin/traffic_server(_ZN7EThread15execute_regularEv+0x474)[0x7c35e4]
/opt/ts/bin/traffic_server[0x7c1fc5]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8064)[0x2b828f6bd064]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x2b82903e062d]

Environment:
ATS 7.1.6
Debian 8, kernel 3.16.0

[masaori335]

It looks like ProxyClientSession::state_api_callout() received unexpected event when the server session reached inactive timeout.
Could you get full backtrace? What event ProxyClientSession::state_api_callout() was received might help us.

[jsnjack]

Hi @masaori335! Many thanks for looking into it!

I have a quite huge log file with output in debug mode from ATS. I have extracted approximately 9k lines prior to the crash (see attached file). I hope it is helpful. Please let me know if I can provide more information somehow.
ats_logs.txt

[bryancall]

@jsnjack If you have a core file it would be great if you can run gdb on it and do a bt full

[bryancall]

@masaori335 My guess is that he is getting a VC_EVENT_INACTIVITY_TIMEOUT event.

[jsnjack]

@bryancall, thanks for the instructions! the original core dump is gone, but the most recent one has the same error. Please check the attached file
ats_core.txt

[masaori335]

@bryancall Right. From the @jsnjack 's full back trace, the event is 105 on frame 5. It's VC_EVENT_INACTIVITY_TIMEOUT.

#4  0x000000000050b1bc in ProxyClientSession::state_api_callout (this=0x2b533400e580, 
    event=<optimized out>, data=<optimized out>) at ProxyClientSession.cc:165
        e = <optimized out>
#5  0x0000000000788040 in handleEvent (data=0x2b5344a2d8b0, event=105, this=0x2b533400e580)
    at /home/jsn/ats_compile/trafficserver-7.1.6/iocore/eventsystem/I_Continuation.h:152
No locals.
#6  read_signal_and_update (vc=0x2b5344a2d780, event=105) at UnixNetVConnection.cc:144
No locals.
#7  UnixNetVConnection::mainEvent (this=0x2b5344a2d780, event=<optimized out>, e=<optimized out>)
    at UnixNetVConnection.cc:1264
        hlock = {m = {m_ptr = 0x2b532c003710}, lock_acquired = true}
        rlock = {m = {m_ptr = 0x2b5374026c80}, lock_acquired = true}
        signal_timeout = <synthetic pointer>
        wlock = {m = {m_ptr = 0x2b5374026c80}, lock_acquired = true}
        signal_event = 105
        reader_cont = 0x2b533400e580
        writer_cont = 0x2b533400e580
        signal_timeout_at = 0x2b5344a2d9b8
        t = 0x0
#8  0x000000000077f4f3 in handleEvent (data=0x16f0be0, event=1, this=0x2b5344a2d780)
    at /home/jsn/ats_compile/trafficserver-7.1.6/iocore/eventsystem/I_Continuation.h:152
No locals.
#9  InactivityCop::check_inactivity (this=0x16a9960, event=<optimized out>, e=0x16f0be0) at UnixNet.cc:76
        vc = 0x2b5344a2d780
        lock = {m = {m_ptr = 0x2b5374020b20}, lock_acquired = true}
        __FUNCTION__ = "check_inactivity"

[jsnjack]

Today we had another crash in the same place but with a different traceback:

#0  0x00002b37dfad1067 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
        resultvar = 0
        pid = 52819
        selftid = 52849
#1  0x00002b37dfad2523 in __GI_abort () at abort.c:118
        act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {18446744073709551615 <repeats 16 times>}}, 
          sa_flags = 0, sa_restorer = 0x0}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00002b37dd6cf3bb in ink_abort (message_format=message_format@entry=0x2b37dd6dbd67 "%s:%d: failed assertion `%s`") at ink_error.cc:99
        ap = {{gp_offset = 32, fp_offset = 48, overflow_arg_area = 0x2b37e3f69ca0, reg_save_area = 0x2b37e3f69be0}}
#3  0x00002b37dd6cd035 in _ink_assert (expression=<optimized out>, file=<optimized out>, line=<optimized out>) at ink_assert.cc:37
No locals.
#4  0x000000000050b1bc in ProxyClientSession::state_api_callout (this=0x2b382401f200, event=<optimized out>, data=<optimized out>)
    at ProxyClientSession.cc:165
        e = <optimized out>
#5  0x000000000078ba0e in handleEvent (data=0x2b38600171b0, event=104, this=<optimized out>)
    at /home/jsn/ats_compile/trafficserver-7.1.6/iocore/eventsystem/I_Continuation.h:152
No locals.
#6  read_signal_and_update (vc=0x2b3860017080, event=104) at UnixNetVConnection.cc:144
No locals.
#7  read_signal_done (vc=0x2b3860017080, nh=0x2b37e2c53eb0, event=104) at UnixNetVConnection.cc:205
No locals.
#8  read_from_net (nh=<optimized out>, vc=0x2b3860017080, thread=<optimized out>) at UnixNetVConnection.cc:355
        b = <optimized out>
        buf = @0x2b38600171d0: {mbuf = 0x2b3820004ed0, entry = 0x0}
        toread = <optimized out>
        total_read = 16384
        r = 0
        lock = {m = {m_ptr = 0x2b37f01c7af0}, lock_acquired = true}
        rattempted = 16384
        __FUNCTION__ = "read_from_net"
        s = 0x2b38600171a8
        niov = <optimized out>
        tiovec = {
# some lines were removed here to make it more readable
}
#9  0x000000000077ba58 in NetHandler::waitForActivity (this=0x2b37e2c53eb0, timeout=<optimized out>) at UnixNet.cc:497
        epd = <optimized out>
        __FUNCTION__ = "waitForActivity"
        poll_timeout = <optimized out>
        lock = {m = {m_ptr = 0x2b37e4002db0}, locked_p = true}
        vc = 0x2b3860017080
#10 0x00000000007c3c27 in EThread::execute_regular (this=0x2b37e2c50010) at UnixEThread.cc:248
        done_one = <optimized out>
        sleep_time = 60000000
        e = <optimized out>
        NegativeQueue = {<DLL<Event, Event::Link_link>> = {head = 0x0}, tail = 0x0}
        next_time = <optimized out>
#11 0x00000000007c1fc5 in spawn_thread_internal (a=0x118a050) at Thread.cc:84
        p = 0x118a050
#12 0x00002b37dee61064 in start_thread (arg=0x2b37e3f6e700) at pthread_create.c:309
        __res = <optimized out>
        pd = 0x2b37e3f6e700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {47519047804672, 4995004970456080233, 0, 22, 140726743067152, 47519047804672, 
                1386569254225600361, 1386668066464751465}, 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>
        __PRETTY_FUNCTION__ = "start_thread"
#13 0x00002b37dfb8462d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

full_tb_5j.txt

[masaori335]

event=104 is VC_EVENT_EOS. ProxySession::state_api_callout() doesn't handle these VC_EVENT_* and making abort, because these events are not expected.

@jsnjack Could you share your use case of ATS? Using as just reverse proxy? I haven't seen this crash with default configs, it's very helpful if we could reproduce this crash easily.

[jsnjack]

We use it as a forward proxy only. I am unable to reproduce it in my test setup, but it happens quite regularly in production. There was some kind of a spike 2 days ago when ats crashed 35 times in 2 hours. I will try to inspect activity on the server during that time frame. Meantime, I have attached records.conf that we are using. I grouped all options that are redefined at the bottom of the file.
ats_records.conf.txt

[jsnjack]

Hi @masaori335,

Looks like the issue is caused by using these 2 options:

CONFIG proxy.config.http.auth_server_session_private INT 1
CONFIG proxy.config.http.attach_server_session_to_client INT 1

If I comment them ATS seems to behave as expected.

I also attached a script you can use to reproduce the issue. It assumes ATS is running on port 8080. The script is going to create many requests to the list of predefined URLs. ATS crashes for me around the request number 11k (sorry, the script is not very pretty!)
run_http.py.txt

[masaori335]

Thanks for the config and scripts for reproducing the issue. It's helpful.

It looks like when proxy.config.http.attach_server_session_to_client is enabled, the attached server session could reach to the timeout while client is requesting different origin server. And the timeout events go to the ProxyClientSession.

@bryancall @shinrich any thoughts?

[mraerino]

we're seeing a similar crash when using the TS_HTTP_SSN_START_HOOK and TS_HTTP_SSN_CLOSE_HOOK in a plugin

this is the backtrace from a coredump i have:

#0  0x00007fde20ccf18b in raise () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007fde20cae92e in abort () from /lib/x86_64-linux-gnu/libc.so.6
#2  0x00007fde2182a046 in ink_abort (message_format=message_format@entry=0x7fde21837ed7 "%s:%d: failed assertion `%s`") at ink_error.cc:99
#3  0x00007fde21827b0f in _ink_assert (expression=expression@entry=0x558cfa082f45 "false", 
    file=file@entry=0x558cfa074f2d "ProxyClientSession.cc", line=line@entry=165) at ink_assert.cc:37
#4  0x0000558cf9daf22c in ProxyClientSession::state_api_callout (this=0x7fde09376660, event=104, data=<optimized out>)
    at ProxyClientSession.cc:165
#5  0x0000558cfa03709d in Continuation::handleEvent (data=0x7fdd6004dff8, event=104, this=<optimized out>)
    at ./iocore/eventsystem/I_Continuation.h:152
#6  read_signal_and_update (vc=0x7fdd6004dec0, event=104) at UnixNetVConnection.cc:144
#7  read_signal_done (vc=0x7fdd6004dec0, nh=0x7fde1bbffed0, event=104) at UnixNetVConnection.cc:205
#8  UnixNetVConnection::readSignalDone (this=this@entry=0x7fdd6004dec0, event=event@entry=104, nh=nh@entry=0x7fde1bbffed0)
    at UnixNetVConnection.cc:1093
#9  0x0000558cfa01a54f in SSLNetVConnection::net_read_io (this=0x7fdd6004dec0, nh=0x7fde1bbffed0, lthread=0x7fde1bbfc010)
    at SSLNetVConnection.cc:637
#10 0x0000558cfa02ba73 in NetHandler::waitForActivity (this=0x7fde1bbffed0, timeout=<optimized out>) at UnixNet.cc:497
#11 0x0000558cfa063861 in EThread::execute_regular (this=this@entry=0x7fde1bbfc010) at UnixEThread.cc:248
#12 0x0000558cfa063e55 in EThread::execute (this=0x7fde1bbfc010) at UnixEThread.cc:278
#13 0x0000558cfa062044 in spawn_thread_internal (a=0x558cfaa08890) at Thread.cc:84
#14 0x00007fde211d7609 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#15 0x00007fde20dab103 in clone () from /lib/x86_64-linux-gnu/libc.so.6

let me know if you need more info 🙂

[mraerino]

i was able to reproduce this crash with the hook-trace plugin (my plugin not present).

it seems when i don't call TSHttpSsnReenable in the TS_HTTP_SSN_CLOSE_HOOK handler of my plugin, it does not crash.
this might leak memory though, right? crashes anyway

[mraerino]

this seems to be related to #6364