ATS 9 NetHandler lock abort

[bryancall]

#0  0x00002ad64a0e7207 in raise () from /lib64/libc.so.6
#0  0x00002ad64a0e7207 in raise () from /lib64/libc.so.6
#1  0x00002ad64a0e88f8 in abort () from /lib64/libc.so.6
#2  0x00002ad64765162b in ink_abort (message_format=message_format@entry=0x2ad6476bae47 "%s:%d: failed assertion `%s`") at ink_error.cc:99
#3  0x00002ad64764ede5 in _ink_assert (expression=expression@entry=0x795e88 "!\"BUG: It must have acquired the NetHandler's lock before doing anything on active_queue.\"", file=file@entry=0x795be0 "UnixNetVConnection.cc", line=line@entry=1471) at ink_assert.cc:37
#4  0x00000000006f4c49 in UnixNetVConnection::add_to_active_queue() () at UnixNetVConnection.cc:1471
#5  0x00000000005bda7c in Http2ConnectionState::create_stream (this=this@entry=0x2ada648ba148, new_id=new_id@entry=497, error=...) at Http2ClientSession.h:191
#6  0x00000000005bea41 in rcv_headers_frame(Http2ConnectionState&, Http2Frame const&) () at Http2ConnectionState.cc:235
#7  0x00000000005c0cd9 in Http2ConnectionState::main_event_handler(int, void*) () at Http2ClientSession.h:95
#8  0x00000000005b5e81 in handleEvent (data=0x2ad651efd3e0, event=2253, this=0x2ada648ba148) at //build_release_posix-x86_64_gcc_8/trafficserver9/iocore/eventsystem/I_Continuation.h:190
#9  handleEvent (data=0x2ad651efd3e0, event=2253, this=0x2ada648ba148) at //build_release_posix-x86_64_gcc_8/trafficserver9/iocore/eventsystem/I_Continuation.h:186
#10 send_connection_event(Continuation*, int, void*) () at Http2ClientSession.cc:65
#11 0x00000000005b6a75 in Http2ClientSession::do_complete_frame_read() () at Http2ClientSession.cc:556
#12 0x00000000005b6edd in Http2ClientSession::state_process_frame_read(int, VIO*, bool) () at Http2ClientSession.cc:610
#13 0x00000000005b7671 in Http2ClientSession::state_start_frame_read (this=0x2ada648b9e00, event=100, edata=0x2ad8d8e0ddd0) at Http2ClientSession.cc:477
#14 0x00000000005b5fe7 in Http2ClientSession::main_event_handler (this=0x2ada648b9e00, event=2257, edata=0x2ad7bd591240) at Http2ClientSession.cc:363
#15 0x0000000000736bfb in handleEvent (data=0x2ad7bd591240, event=2257, this=0x2ada648b9e00) at I_Continuation.h:190
#16 handleEvent (data=0x2ad7bd591240, event=2257, this=0x2ada648b9e00) at I_Continuation.h:186
#17 EThread::process_event(Event*, int) () at UnixEThread.cc:136
#18 0x0000000000737abc in EThread::execute_regular (this=this@entry=0x2ad64d7ddbc0) at UnixEThread.cc:249
#19 0x0000000000737eaa in execute (this=0x2ad64d7ddbc0) at UnixEThread.cc:338
#20 EThread::execute (this=0x2ad64d7ddbc0) at UnixEThread.cc:316
#21 0x0000000000736309 in spawn_thread_internal (a=0x2ad64c193e00) at Thread.cc:92
#22 0x00002ad649479dd5 in start_thread () from /lib64/libpthread.so.0
#23 0x00002ad64a1aeead in clone () from /lib64/libc.so.6

[bryancall]

The problem why I am seeing this crash is because of global session pool thread migration. Here is the coredump after making the ProxyMutex have a thread affinity and core if some other thread tries to grab the lock:

#0  0x00002b95fd320207 in raise () from /lib64/libc.so.6
#0  0x00002b95fd320207 in raise () from /lib64/libc.so.6
#1  0x00002b95fd3218f8 in abort () from /lib64/libc.so.6
#2  0x00002b95fa88a62b in ink_abort (message_format=message_format@entry=0x2b95fa8f3e47 "%s:%d: failed assertion `%s`") at ink_error.cc:99
#3  0x00002b95fa887de5 in _ink_assert (expression=expression@entry=0x73d780 "t == m->getThreadAffinity()", file=file@entry=0x73d8e0 "/sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/iocore/eventsystem/I_Lock.h", line=line@entry=252) at ink_assert.cc:37
#4  0x00000000006fb279 in Mutex_trylock (t=0x2b9600800f00, m=...) at /sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/iocore/eventsystem/I_ThreadAffinity.h:43
#5  MutexTryLock (t=0x2b9600800f00, am=..., this=0x2b9603202010) at /sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/iocore/eventsystem/I_Lock.h:399
#6  UnixNetVConnection::migrateToCurrentThread(Continuation*, EThread*) () at UnixNetVConnection.cc:1378
#7  0x0000000000553798 in HttpSessionManager::acquire_session(Continuation*, sockaddr const*, char const*, ProxyTransaction*, HttpSM*) () at HttpSessionManager.cc:342
#8  0x000000000054787d in HttpSM::do_http_server_open(bool) () at HttpSM.cc:4814
#9  0x000000000054a228 in HttpSM::set_next_state (this=0x2b978bd40000) at HttpSM.cc:7318
#10 0x000000000053400f in HttpSM::call_transact_and_set_next_state (this=this@entry=0x2b978bd40000, f=f@entry=0x0) at HttpSM.cc:7116
#11 0x00000000005364d4 in HttpSM::state_cache_open_write (this=0x2b978bd40000, event=1109, data=0xffffffffffffb04f) at HttpSM.cc:2455
#12 0x0000000000541e63 in main_handler (data=0xffffffffffffb04f, event=1109, this=0x2b978bd40000) at HttpSM.cc:2568
#13 HttpSM::main_handler (this=0x2b978bd40000, event=1109, data=0xffffffffffffb04f) at HttpSM.cc:2538
#14 0x000000000058f425 in handleEvent (data=0xffffffffffffb04f, event=1109, this=0x2b978bd40000) at /sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/iocore/eventsystem/I_Continuation.h:167
#15 handleEvent (data=0xffffffffffffb04f, event=1109, this=0x2b978bd40000) at /sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/iocore/eventsystem/I_Continuation.h:163
#16 HttpCacheSM::open_write (this=this@entry=0x2b978bd41d60, key=key@entry=0x2b978bd41e20, url=<optimized out>, request=<optimized out>, old_info=<optimized out>, pin_in_cache=<optimized out>, retry=true, allow_multiple=false) at HttpCacheSM.cc:322
#17 0x000000000058f5e3 in HttpCacheSM::state_cache_open_write (this=0x2b978bd41d60, event=2, data=0x2b977d1a1440) at HttpCacheSM.cc:199
#18 0x0000000000737963 in handleEvent (data=0x2b977d1a1440, event=2, this=0x2b978bd41d60) at I_Continuation.h:167
#19 handleEvent (data=0x2b977d1a1440, event=2, this=0x2b978bd41d60) at I_Continuation.h:163
#20 EThread::process_event(Event*, int) () at UnixEThread.cc:136
#21 0x000000000073886c in EThread::execute_regular (this=this@entry=0x2b9600800f00) at UnixEThread.cc:249
#22 0x0000000000738ca6 in execute (this=0x2b9600800f00) at UnixEThread.cc:338
#23 EThread::execute (this=0x2b9600800f00) at UnixEThread.cc:316
#24 0x0000000000736f19 in spawn_thread_internal (a=0x2b95ff393c80) at Thread.cc:92
#25 0x00002b95fc6b2dd5 in start_thread () from /lib64/libpthread.so.0
#26 0x00002b95fd3e7ead in clone () from /lib64/libc.so.6

[shinrich]

The grabbing of the net handler thread was logic added by @oknet to try to preserve the existing netvc object and simply move it to another thread. At this point the logic is holding (briefly) the mutex for the nethandlers of two threads.

The original logic always created new netvc objects on the target thread and moved the key information over (fd and ssl object).

[shinrich]

I've been running with logic that reverts the logic that tries to preserve the existing netvc object, and that has been running without incident. In that logic, the migration thread does not need to grab the other thread's net handler lock. The epoll call to remove the file descriptor from the original thread's epoll descriptor is thread save. Then do_io_close only sets the close flag on the netvc if the netvc is not associated with the current thread. The next time through the inactivity cop on the original thread will free the netvc objects with the close flag set and take it out of the keep_alive queue.

[oknet]

1377   // Try to get the mutex lock for NetHandler of this NetVC
1378   MUTEX_TRY_LOCK(lock_src, this->nh->mutex, t);

The this->nh is running at another EThread, the the nh->mutex has thread affinity for another EThread.

The line 1378 of UnixNetVConnection.cc just do one thing: try lock a ProxyMutex across EThread, it is a common operation.

[zwoop]

Resolved.