reloading remap.config with causing a segmentation fault

[jrushford]

While load testing a 'master' branch build using a remap with the cachkey plugin enabled, traffic server crashed due to a segmentation fault after making changes to remap.config followed by traffic_ctl config reload.

I tracked it down to the cachekey plugin. After removing the plugin configuration and repeating the test, edit remap.config; traffic_ctl config reload, its no-longer crashes.

Here is my remap.config with the cachekey plugin:

map http://foo.com:8080 http://cache-01.foo.com:8080/ @strategy=bar.com @plugin=cachekey.so @pparam=--separator= @pparam=--remove-all-params=true @pparam=--remove-path=true @pparam=--capture-prefix-uri=/^([^?]*)/$1/

Here are the stack traces:

traffic_server: received signal 11 (Segmentation fault) traffic_server - STACK TRACE: /opt/trafficserver/bin/traffic_server(crash_logger_invoke(int, siginfo_t*, void*)+0xc3)[0x6394db] /lib64/libpthread.so.0(+0xf5d0)[0x2ac8695555d0] /lib64/libc.so.6(+0x155866)[0x2ac86a2da866] /opt/trafficserver/bin/traffic_server(std::char_traits<char>::copy(char*, char const*, unsigned long)+0x3e)[0x63179a] /opt/trafficserver/bin/traffic_server(std::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_copy(char*, char const*, unsigned long)+0x47)[0x634f66] /opt/trafficserver/bin/traffic_server(std::basic_string<char, std::char_traits<char>, std::allocator<char> >::_Rep::_M_clone(std::allocator<char> const&, unsigned long)+0x84)[0x6354f2] /opt/trafficserver/bin/traffic_server(std::basic_string<char, std::char_traits<char>, std::allocator<char> >::_Rep::_M_grab(std::allocator<char> const&, std::allocator<char> const&)+0x64)[0x634552] /opt/trafficserver/bin/traffic_server(std::basic_string<char, std::char_traits<char>, std::allocator<char> >::basic_string(std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)+0x72)[0x633a30] /opt/trafficserver/var/trafficserver/3a39165c-3815-405e-8621-a9b0c1111b4c/opt/trafficserver/libexec/trafficserver/cachekey.so(+0x3b909)[0x2ac9122de909] /opt/trafficserver/var/trafficserver/3a39165c-3815-405e-8621-a9b0c1111b4c/opt/trafficserver/libexec/trafficserver/cachekey.so(TSRemapDoRemap+0x3a)[0x2ac9122deec7] /opt/trafficserver/bin/traffic_server(RemapPluginInfo::doRemap(void*, tsapi_httptxn*, _tm_remap_request_info*)+0x57)[0x767d3d] /opt/trafficserver/bin/traffic_server(RemapPluginInst::doRemap(tsapi_httptxn*, _tm_remap_request_info*)+0x34)[0x74e88e] /opt/trafficserver/bin/traffic_server(RemapPlugins::run_plugin(RemapPluginInst*)+0xfd)[0x76ab13] /opt/trafficserver/bin/traffic_server(RemapPlugins::run_single_remap()+0x1fe)[0x76ad6c] /opt/trafficserver/bin/traffic_server(RemapProcessor::perform_remap(Continuation*, HttpTransact::State*)+0x318)[0x753bfc] /opt/trafficserver/bin/traffic_server(HttpSM::do_remap_request(bool)+0x499)[0x6d18c3] /opt/trafficserver/bin/traffic_server(HttpSM::set_next_state()+0xa7)[0x6dec35] /opt/trafficserver/bin/traffic_server(HttpSM::call_transact_and_set_next_state(void (*)(HttpTransact::State*))+0x1b8)[0x6deb84] /opt/trafficserver/bin/traffic_server(HttpSM::handle_api_return()+0x1ac)[0x6c7552] /opt/trafficserver/bin/traffic_server(HttpSM::state_api_callout(int, void*)+0xc95)[0x6c7261] /opt/trafficserver/bin/traffic_server(HttpSM::do_api_callout_internal()+0x218)[0x6d6a50] /opt/trafficserver/bin/traffic_server(HttpSM::do_api_callout()+0x27)[0x6e707f] /opt/trafficserver/bin/traffic_server(HttpSM::set_next_state()+0x60)[0x6debee] /opt/trafficserver/bin/traffic_server(HttpSM::call_transact_and_set_next_state(void (*)(HttpTransact::State*))+0x1b8)[0x6deb84] /opt/trafficserver/bin/traffic_server(HttpSM::handle_api_return()+0x1ac)[0x6c7552] /opt/trafficserver/bin/traffic_server(HttpSM::state_api_callout(int, void*)+0xc95)[0x6c7261] /opt/trafficserver/bin/traffic_server(HttpSM::state_api_callback(int, void*)+0x1e4)[0x6c6550] /opt/trafficserver/bin/traffic_server(TSHttpTxnReenable+0x109)[0x65489d] /opt/trafficserver/libexec/trafficserver/remap_stats.so(+0xcb5e)[0x2ac910972b5e] /opt/trafficserver/bin/traffic_server(INKContInternal::handle_event(int, void*)+0x13a)[0x6479de] /opt/trafficserver/bin/traffic_server(Continuation::handleEvent(int, void*)+0xc9)[0x63d7ed] /opt/trafficserver/bin/traffic_server(APIHook::invoke(int, void*) const+0xe9)[0x6483af] /opt/trafficserver/bin/traffic_server(HttpSM::state_api_callout(int, void*)+0x922)[0x6c6eee] /opt/trafficserver/bin/traffic_server(HttpSM::state_api_callback(int, void*)+0x1e4)[0x6c6550] /opt/trafficserver/bin/traffic_server(TSHttpTxnReenable+0x109)[0x65489d] /opt/trafficserver/libexec/trafficserver/stats_over_http.so(+0x1d07)[0x2ac910763d07] /opt/trafficserver/bin/traffic_server(INKContInternal::handle_event(int, void*)+0x13a)[0x6479de] /opt/trafficserver/bin/traffic_server(Continuation::handleEvent(int, void*)+0xc9)[0x63d7ed] /opt/trafficserver/bin/traffic_server(APIHook::invoke(int, void*) const+0xe9)[0x6483af] /opt/trafficserver/bin/traffic_server(HttpSM::state_api_callout(int, void*)+0x922)[0x6c6eee] /opt/trafficserver/bin/traffic_server(HttpSM::main_handler(int, void*)+0x35e)[0x6cc0f4] /opt/trafficserver/bin/traffic_server(Continuation::handleEvent(int, void*)+0xc9)[0x63d7ed] /opt/trafficserver/bin/traffic_server(EThread::process_event(Event*, int)+0x143)[0x927ce7] /opt/trafficserver/bin/traffic_server(EThread::execute_regular()+0x2c4)[0x9282c2] /opt/trafficserver/bin/traffic_server(EThread::execute()+0x107)[0x928601] /opt/trafficserver/bin/traffic_server[0x927125] /lib64/libpthread.so.0(+0x7dd5)[0x2ac86954ddd5] /lib64/libc.so.6(clone+0x6d)[0x2ac86a28302d] traffic_server: received signal 11 (Segmentation fault) traffic_server - STACK TRACE: /opt/trafficserver/bin/traffic_server(crash_logger_invoke(int, siginfo_t*, void*)+0xc3)[0x6394db] /lib64/libpthread.so.0(+0xf5d0)[0x2b800ee9f5d0] /opt/trafficserver/bin/traffic_server[0x631230] /opt/trafficserver/bin/traffic_server(RefCountObj::refcount_inc()+0x21)[0x631a07] /opt/trafficserver/bin/traffic_server(Ptr<ProxyMutex>::Ptr(Ptr<ProxyMutex> const&)+0x39)[0x63f0f1] /opt/trafficserver/bin/traffic_server(WeakMutexTryLock::WeakMutexTryLock(SourceLocation const&, char const*, Ptr<ProxyMutex>&, EThread*)+0x30)[0x65efd4] /opt/trafficserver/bin/traffic_server(HttpSM::state_api_callout(int, void*)+0x665)[0x6c6c31] /opt/trafficserver/bin/traffic_server(HttpSM::do_api_callout_internal()+0x218)[0x6d6a50] /opt/trafficserver/bin/traffic_server(HttpSM::do_api_callout()+0x27)[0x6e707f] /opt/trafficserver/bin/traffic_server(HttpSM::setup_cache_lookup_complete_api()+0x26)[0x6e7204] /opt/trafficserver/bin/traffic_server(HttpSM::state_cache_open_read(int, void*)+0x654)[0x6cbd72] /opt/trafficserver/bin/traffic_server(HttpSM::main_handler(int, void*)+0x35e)[0x6cc0f4] /opt/trafficserver/bin/traffic_server(Continuation::handleEvent(int, void*)+0xc9)[0x63d7ed] /opt/trafficserver/bin/traffic_server(HttpCacheSM::state_cache_open_read(int, void*)+0x2a7)[0x7309c5] /opt/trafficserver/bin/traffic_server(Continuation::handleEvent(int, void*)+0xc9)[0x63d7ed] /opt/trafficserver/bin/traffic_server(CacheVC::openReadStartHead(int, Event*)+0x10b8)[0x859bce] /opt/trafficserver/bin/traffic_server(CacheVC::openReadFromWriter(int, Event*)+0x2ef)[0x853a07] /opt/trafficserver/bin/traffic_server(Continuation::handleEvent(int, void*)+0xc9)[0x63d7ed] /opt/trafficserver/bin/traffic_server(EThread::process_event(Event*, int)+0x143)[0x927ce7] /opt/trafficserver/bin/traffic_server(EThread::execute_regular()+0x2c4)[0x9282c2] /opt/trafficserver/bin/traffic_server(EThread::execute()+0x107)[0x928601] /opt/trafficserver/bin/traffic_server[0x927125] /lib64/libpthread.so.0(+0x7dd5)[0x2b800ee97dd5] /lib64/libc.so.6(clone+0x6d)[0x2b800fbcd02d] [TrafficManager] ==> Cleaning up and reissuing signal #15 traffic_server: using root directory '/opt/trafficserver' [TrafficManager] ==> signal #15

[jrushford]

Initially, I thought this was only an issue when using the cachekey plugin in remap.config but this is not the case. It crashes with just a reload. Here are two stack traces I was able to cabture. This is common to both crashes: WeakMutexTryLock::WeakMutexTryLock (this=0x2b9b81705a60, location=..., ahandler=0x0, am=..., t=0x2b9b7a380010) at /home/jrushf1239k/trafficserver-apache/iocore/eventsystem/I_Lock.h:472

#0  0x0000000000632f44 in ink_atomic_increment<int, int> (mem=0xefbeaddeefbeade6, count=1)
    at ../include/tscore/ink_atomic.h:78
#1  0x0000000000633615 in RefCountObj::refcount_inc (this=0xefbeaddeefbeadde) at ../include/tscore/Ptr.h:66
#2  0x0000000000640e7f in Ptr<ProxyMutex>::Ptr (this=0x2b9b81705a60, src=...) at ../include/tscore/Ptr.h:200
#3  0x0000000000661038 in WeakMutexTryLock::WeakMutexTryLock (this=0x2b9b81705a60, location=..., ahandler=0x0,
    am=..., t=0x2b9b7a380010) at /home/jrushf1239k/trafficserver-apache/iocore/eventsystem/I_Lock.h:472
#4  0x00000000006ca60e in HttpSM::state_api_callout (this=0x2b9c6a923c00, event=2, data=0x2b9c6c0242c0)
    at HttpSM.cc:1456
#5  0x00000000006cfae6 in HttpSM::main_handler (this=0x2b9c6a923c00, event=2, data=0x2b9c6c0242c0)
    at HttpSM.cc:2620
#6  0x000000000063f57b in Continuation::handleEvent (this=0x2b9c6a923c00, event=2, data=0x2b9c6c0242c0)
    at /home/jrushf1239k/trafficserver-apache/iocore/eventsystem/I_Continuation.h:190
#7  0x0000000000934ad5 in EThread::process_event (this=0x2b9b7a380010, e=0x2b9c6c0242c0, calling_code=2)
    at UnixEThread.cc:126
#8  0x00000000009350b0 in EThread::execute_regular (this=0x2b9b7a380010) at UnixEThread.cc:239
#9  0x00000000009353ef in EThread::execute (this=0x2b9b7a380010) at UnixEThread.cc:330
#10 0x0000000000933e81 in spawn_thread_internal (a=0x121a570) at Thread.cc:92
#11 0x00002b9b7766fe25 in start_thread () from /lib64/libpthread.so.0
#12 0x00002b9b783a034d in clone () from /lib64/libc.so.6```



```(gdb) bt
#0  0x0000000000632f44 in ink_atomic_increment<int, int> (mem=0xefbeaddeefbeade6, count=1)
    at ../include/tscore/ink_atomic.h:78
#1  0x0000000000633615 in RefCountObj::refcount_inc (this=0xefbeaddeefbeadde) at ../include/tscore/Ptr.h:66
#2  0x0000000000640e7f in Ptr<ProxyMutex>::Ptr (this=0x2ae6bfe2f5d0, src=...) at ../include/tscore/Ptr.h:200
#3  0x0000000000661038 in WeakMutexTryLock::WeakMutexTryLock (this=0x2ae6bfe2f5d0, location=..., ahandler=0x0,
    am=..., t=0x2ae6b7480010) at /home/jrushf1239k/trafficserver-apache/iocore/eventsystem/I_Lock.h:472
#4  0x00000000006ca60e in HttpSM::state_api_callout (this=0x2ae6d4f92800, event=0, data=0x0) at HttpSM.cc:1456
#5  0x00000000006da400 in HttpSM::do_api_callout_internal (this=0x2ae6d4f92800) at HttpSM.cc:5154
#6  0x00000000006ea85d in HttpSM::do_api_callout (this=0x2ae6d4f92800) at HttpSM.cc:397
#7  0x00000000006ea9dc in HttpSM::setup_cache_lookup_complete_api (this=0x2ae6d4f92800) at HttpSM.cc:2516
#8  0x00000000006cf6f2 in HttpSM::state_cache_open_read (this=0x2ae6d4f92800, event=1103,
    data=0xffffffffffffb050) at HttpSM.cc:2578
#9  0x00000000006cfae6 in HttpSM::main_handler (this=0x2ae6d4f92800, event=1103, data=0xffffffffffffb050)
    at HttpSM.cc:2620
#10 0x000000000063f57b in Continuation::handleEvent (this=0x2ae6d4f92800, event=1103, data=0xffffffffffffb050)
    at /home/jrushf1239k/trafficserver-apache/iocore/eventsystem/I_Continuation.h:190
#11 0x0000000000735001 in HttpCacheSM::state_cache_open_read (this=0x2ae6d4f945a8, event=1103,
    data=0xffffffffffffb050) at HttpCacheSM.cc:133
#12 0x000000000063f57b in Continuation::handleEvent (this=0x2ae6d4f945a8, event=1103, data=0xffffffffffffb050)
    at /home/jrushf1239k/trafficserver-apache/iocore/eventsystem/I_Continuation.h:190
#13 0x00000000008624eb in CacheVC::openReadStartHead (this=0x2ae7700472a0, event=2, e=0x2b0b760)
    at CacheRead.cc:1198
#14 0x000000000063f57b in Continuation::handleEvent (this=0x2ae7700472a0, event=2, data=0x2b0b760)
    at /home/jrushf1239k/trafficserver-apache/iocore/eventsystem/I_Continuation.h:190
#15 0x0000000000934ad5 in EThread::process_event (this=0x2ae6b7480010, e=0x2b0b760, calling_code=2)
    at UnixEThread.cc:126
#16 0x00000000009350b0 in EThread::execute_regular (this=0x2ae6b7480010) at UnixEThread.cc:239
#17 0x00000000009353ef in EThread::execute (this=0x2ae6b7480010) at UnixEThread.cc:330
#18 0x0000000000933e81 in spawn_thread_internal (a=0x2b01ef0) at Thread.cc:92
#19 0x00002ae6b1e74e25 in start_thread () from /lib64/libpthread.so.0
#20 0x00002ae6b2ba534d in clone () from /lib64/libc.so.6```

[traeak]

This might be related to #6231 and the new WEAK_MUTEX_TRY_LOCK ... nope ... recreated in checkin prior to PR 6231.

[gtenev]

@traeak, @jrushford is this happening with 9.x branch? (basically trying to get a sense of when it started happening)

[jrushford]

@gtenev yes it crashes on both ATS 9.0 and on master. I'm testing on a machine under load with http requests. If I touch the remap.config and then use traffic_ctl config reload, it crashes with the above stack trace where it's trying to increment the reference count on a plugin continuation mutex than no-longer exists. I walked back through all the commits over the past few days and found that it started crashing with this commit:

`commit 1eca389
Author: Gancho Tenev gancho@apache.org
Date: Fri Mar 1 14:33:09 2019 -0800

Plugin reload

Reloading plugin allows new versions of a plugin code to be loaded
and executed and old versions to be unloaded without restarting
the traffic server process.

More info in doc/developer-guide/plugins/reloading-plugins.en.rst`

If I build with head set to ad7bfc4deadb73fef3301afb9a605e0da5cb9426 one commit before the Plugin reload commit. ATS no-longer crashes with the traffic_ctl reload on 9 and on master.

[gtenev]

Thank you, John, for reporting and narrowing the problem down to the particular commit that causes it. I was able to reproduce it with the test case you provided under load and got the exact same crash.

In some plugins TSRemapDeleteInstance callbacks perform cleanup by deleting continuations created by the plugin. In certain conditions like in the test case provided state machines were still alive after the continuation cleanup and attempted to use them. PR #6280 provides a fix for the problem, basically delaying the callbacks calls until all state machines are finished and gone.

[jrushford]

Fixed by #6280 and #6299