ASAN: heap-buffer-overflow in InactivityCop

[zwoop]

==26076==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x6250008cc918 at pc 0x000000e096e6 bp 0x2b88973a8600 sp 0x2b88973a85f0
READ of size 8 at 0x6250008cc918 thread T2 ([ET_NET 0])
    #0 0xe096e5 in Ptr<ProxyMutex>::operator bool() const ../../include/tscore/Ptr.h:112
    #1 0xe096e5 in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:189
    #2 0xe096e5 in read_signal_and_update /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:83
    #3 0xe0e7fa in UnixNetVConnection::mainEvent(int, Event*) /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:1148
    #4 0xde3cef in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
    #5 0xde3cef in InactivityCop::check_inactivity(int, Event*) /usr/local/src/trafficserver/iocore/net/UnixNet.cc:85
    #6 0xf290ac in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
    #7 0xf290ac in EThread::process_event(Event*, int) /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:136
    #8 0xf2b9ad in EThread::execute_regular() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:249
    #9 0xf2cd71 in EThread::execute() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:338
    #10 0xf2717a in spawn_thread_internal /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:92
    #11 0x2b8891a17e64 in start_thread (/lib64/libpthread.so.0+0x7e64)
    #12 0x2b889274d88c in clone (/lib64/libc.so.6+0xfe88c)

Address 0x6250008cc918 is a wild pointer.
SUMMARY: AddressSanitizer: heap-buffer-overflow ../../include/tscore/Ptr.h:112 in Ptr<ProxyMutex>::operator bool() const
Shadow bytes around the buggy address:
  0x0c4a801118d0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a801118e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a801118f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a80111900: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a80111910: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
=>0x0c4a80111920: fa fa fa[fa]fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a80111930: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a80111940: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a80111950: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a80111960: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a80111970: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
Thread T2 ([ET_NET 0]) created by T0 ([TS_MAIN]) here:
    #0 0x2b888f0c1a7f in pthread_create (/lib64/libasan.so.4+0x37a7f)
    #1 0xf282de in ink_thread_create ../../include/tscore/ink_thread.h:159
    #2 0xf282de in Thread::start(char const*, void*, unsigned long, std::function<void ()> const&) /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:109
    #3 0xf366ff in EventProcessor::spawn_event_threads(int, int, unsigned long) /usr/local/src/trafficserver/iocore/eventsystem/UnixEventProcessor.cc:392
    #4 0xf37935 in EventProcessor::start(int, unsigned long) /usr/local/src/trafficserver/iocore/eventsystem/UnixEventProcessor.cc:455
    #5 0x4c05c8 in main traffic_server/traffic_server.cc:1982
    #6 0x2b8892671504 in __libc_start_main (/lib64/libc.so.6+0x22504)

==26076==ABORTING

[zwoop]

Also, I think this ASAN is related as well, also triggered via InactivityCop:

==7400==ERROR: AddressSanitizer: heap-use-after-free on address 0x625001487118 at pc 0x000000e096e6 bp 0x2aaf7bc9c600 sp 0x2aaf7bc9c5f0
READ of size 8 at 0x625001487118 thread T4 ([ET_NET 2])
    #0 0xe096e5 in Ptr<ProxyMutex>::operator bool() const ../../include/tscore/Ptr.h:112
    #1 0xe096e5 in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:189
    #2 0xe096e5 in read_signal_and_update /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:83
    #3 0xe0e7fa in UnixNetVConnection::mainEvent(int, Event*) /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:1148
    #4 0xde3cef in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
    #5 0xde3cef in InactivityCop::check_inactivity(int, Event*) /usr/local/src/trafficserver/iocore/net/UnixNet.cc:85
    #6 0xf290ac in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
    #7 0xf290ac in EThread::process_event(Event*, int) /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:136
    #8 0xf2b9ad in EThread::execute_regular() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:249
    #9 0xf2cd71 in EThread::execute() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:338
    #10 0xf2717a in spawn_thread_internal /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:92
    #11 0x2aaf75e6ce64 in start_thread (/lib64/libpthread.so.0+0x7e64)
    #12 0x2aaf76ba288c in clone (/lib64/libc.so.6+0xfe88c)

0x625001487118 is located 24 bytes inside of 9120-byte region [0x625001487100,0x6250014894a0)
freed by thread T8 ([ET_NET 6]) here:
    #0 0x2aaf735bd508 in __interceptor_free (/lib64/libasan.so.4+0xde508)
    #1 0x2aaf745b2a0c in ink_freelist_free /usr/local/src/trafficserver/src/tscore/ink_queue.cc:277
    #2 0x6e18b2 in HttpSM::kill_this() /usr/local/src/trafficserver/proxy/http/HttpSM.cc:6893
    #3 0x6e2707 in HttpSM::main_handler(int, void*) /usr/local/src/trafficserver/proxy/http/HttpSM.cc:2588
    #4 0x7f337b in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
    #5 0x7f337b in HttpTunnel::main_handler(int, void*) /usr/local/src/trafficserver/proxy/http/HttpTunnel.cc:1579
    #6 0xe0b470 in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
    #7 0xe0b470 in write_signal_and_update /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:114
    #8 0xe0b470 in write_signal_done /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:156
    #9 0xe1f960 in write_to_net_io(NetHandler*, UnixNetVConnection*, EThread*) /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:497
    #10 0xdd321b in NetHandler::process_ready_list() /usr/local/src/trafficserver/iocore/net/UnixNet.cc:417
    #11 0xdd3dd8 in NetHandler::waitForActivity(long) /usr/local/src/trafficserver/iocore/net/UnixNet.cc:535
    #12 0xf2c421 in EThread::execute_regular() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:277
    #13 0xf2cd71 in EThread::execute() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:338
    #14 0xf2717a in spawn_thread_internal /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:92
    #15 0x2aaf75e6ce64 in start_thread (/lib64/libpthread.so.0+0x7e64)

previously allocated by thread T8 ([ET_NET 6]) here:
    #0 0x2aaf735be4f0 in posix_memalign (/lib64/libasan.so.4+0xdf4f0)
    #1 0x2aaf745b08df in ats_memalign /usr/local/src/trafficserver/src/tscore/ink_memory.cc:102
    #2 0x2aaf745b296e in ink_freelist_new /usr/local/src/trafficserver/src/tscore/ink_queue.cc:187
    #3 0xcebf40 in ClassAllocator<HttpSM>::alloc() ../include/tscore/Allocator.h:131
    #4 0xcebf40 in HttpSM::allocate() http/HttpSM.h:662
    #5 0xcebf40 in ProxyTransaction::new_transaction() /usr/local/src/trafficserver/proxy/ProxyTransaction.cc:41
    #6 0x64d9a4 in Http1ClientSession::new_transaction() /usr/local/src/trafficserver/proxy/http/Http1ClientSession.cc:463
    #7 0x64d9a4 in Http1ClientSession::state_keep_alive(int, void*) /usr/local/src/trafficserver/proxy/http/Http1ClientSession.cc:383
    #8 0xe12410 in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
    #9 0xe12410 in read_signal_and_update /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:83
    #10 0xe12410 in UnixNetVConnection::readSignalAndUpdate(int) /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:1006
    #11 0xd74635 in SSLNetVConnection::net_read_io(NetHandler*, EThread*) /usr/local/src/trafficserver/iocore/net/SSLNetVConnection.cc:638
    #12 0xdd31da in NetHandler::process_ready_list() /usr/local/src/trafficserver/iocore/net/UnixNet.cc:400
    #13 0xdd3dd8 in NetHandler::waitForActivity(long) /usr/local/src/trafficserver/iocore/net/UnixNet.cc:535
    #14 0xf2c421 in EThread::execute_regular() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:277
    #15 0xf2cd71 in EThread::execute() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:338
    #16 0xf2717a in spawn_thread_internal /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:92
    #17 0x2aaf75e6ce64 in start_thread (/lib64/libpthread.so.0+0x7e64)

Thread T4 ([ET_NET 2]) created by T0 ([TS_MAIN]) here:
    #0 0x2aaf73516a7f in pthread_create (/lib64/libasan.so.4+0x37a7f)
    #1 0xf282de in ink_thread_create ../../include/tscore/ink_thread.h:159
    #2 0xf282de in Thread::start(char const*, void*, unsigned long, std::function<void ()> const&) /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:109
    #3 0xf366ff in EventProcessor::spawn_event_threads(int, int, unsigned long) /usr/local/src/trafficserver/iocore/eventsystem/UnixEventProcessor.cc:392
    #4 0xf37935 in EventProcessor::start(int, unsigned long) /usr/local/src/trafficserver/iocore/eventsystem/UnixEventProcessor.cc:455
    #5 0x4c05c8 in main traffic_server/traffic_server.cc:1982
    #6 0x2aaf76ac6504 in __libc_start_main (/lib64/libc.so.6+0x22504)

Thread T8 ([ET_NET 6]) created by T0 ([TS_MAIN]) here:
    #0 0x2aaf73516a7f in pthread_create (/lib64/libasan.so.4+0x37a7f)
    #1 0xf282de in ink_thread_create ../../include/tscore/ink_thread.h:159
    #2 0xf282de in Thread::start(char const*, void*, unsigned long, std::function<void ()> const&) /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:109
    #3 0xf366ff in EventProcessor::spawn_event_threads(int, int, unsigned long) /usr/local/src/trafficserver/iocore/eventsystem/UnixEventProcessor.cc:392
    #4 0xf37935 in EventProcessor::start(int, unsigned long) /usr/local/src/trafficserver/iocore/eventsystem/UnixEventProcessor.cc:455
    #5 0x4c05c8 in main traffic_server/traffic_server.cc:1982
    #6 0x2aaf76ac6504 in __libc_start_main (/lib64/libc.so.6+0x22504)

SUMMARY: AddressSanitizer: heap-use-after-free ../../include/tscore/Ptr.h:112 in Ptr<ProxyMutex>::operator bool() const
Shadow bytes around the buggy address:
  0x0c4a80288dd0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a80288de0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a80288df0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a80288e00: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c4a80288e10: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
=>0x0c4a80288e20: fd fd fd[fd]fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a80288e30: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a80288e40: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a80288e50: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a80288e60: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c4a80288e70: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==7400==ABORTING

[shinrich]

With our latest sync of our 9.0.x branch with the ASF 9.0.x branch we are seeing core files from production traffic similar to these stacks. About once every 5 minutes. In our cases it seems that an inactivity event triggers on a HttpSM that has already been deleted or has been reallocated already.

[shinrich]

I reverted @masaori335's co,mit dac1489 and we were able to running the resulting build on the same machine overnight. Previously we got 6 cores in 30 minutes with one of the following core dumps.

(gdb) bt
#0  0x00002ba4e5695207 in raise () from /lib64/libc.so.6
#1  0x00002ba4e56968f8 in abort () from /lib64/libc.so.6
#2  0x00002ba4e2df498b in ink_abort (message_format=message_format@entry=0x2ba4e2e5f4e7 "%s:%d: failed assertion `%s`") at ../../../../../../_vcs/trafficserver9/src/tscore/ink_error.cc:99
#3  0x00002ba4e2df2145 in _ink_assert (expression=expression@entry=0x75c4ba "magic == HTTP_SM_MAGIC_ALIVE", file=file@entry=0x759600 "../../../../../../_vcs/trafficserver9/proxy/http/HttpSM.cc", 
    line=line@entry=2572) at ../../../../../../_vcs/trafficserver9/src/tscore/ink_assert.cc:37
#4  0x0000000000544457 in HttpSM::main_handler (this=<optimized out>, event=<optimized out>, data=<optimized out>) at ../../../../../../_vcs/trafficserver9/proxy/http/HttpSM.cc:2572
#5  0x00000000006f8e25 in handleEvent (data=0x2ba799fecd50, event=105, this=0x2ba78695a960)
    at /sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/build/../../../../_vcs/trafficserver9/iocore/eventsystem/I_Continuation.h:167
#6  handleEvent (data=0x2ba799fecd50, event=105, this=0x2ba78695a960)
    at /sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/build/../../../../_vcs/trafficserver9/iocore/eventsystem/I_Continuation.h:163
#7  read_signal_and_update (event=105, vc=0x2ba799fecb80) at ../../../../../../_vcs/trafficserver9/iocore/net/UnixNetVConnection.cc:83
#8  0x00000000006fd30c in UnixNetVConnection::mainEvent(int, Event*) () at ../../../../../../_vcs/trafficserver9/iocore/net/UnixNetVConnection.cc:1152
#9  0x00000000006f0f0d in handleEvent (data=0x2ba4e67fb6e0, event=105, this=0x2ba799fecb80)
    at /sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/build/../../../../_vcs/trafficserver9/iocore/eventsystem/I_Continuation.h:167
#10 handleEvent (data=0x2ba4e67fb6e0, event=105, this=0x2ba799fecb80)
    at /sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/build/../../../../_vcs/trafficserver9/iocore/eventsystem/I_Continuation.h:163
#11 InactivityCop::check_inactivity (this=0x2ba4ec0c3000, event=<optimized out>, e=<optimized out>) at ../../../../../../_vcs/trafficserver9/iocore/net/UnixNet.cc:81
#12 0x000000000073b1f7 in handleEvent (data=0x2ba4e67fb6e0, event=2, this=0x2ba4ec0c3000) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/I_Continuation.h:167
#13 handleEvent (data=0x2ba4e67fb6e0, event=2, this=0x2ba4ec0c3000) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/I_Continuation.h:163
#14 EThread::process_event(Event*, int) () at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/UnixEThread.cc:136
#15 0x000000000073c084 in EThread::execute_regular (this=this@entry=0x2ba4e829a080) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/UnixEThread.cc:249
#16 0x000000000073c4a6 in execute (this=0x2ba4e829a080) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/UnixEThread.cc:344
#17 EThread::execute (this=0x2ba4e829a080) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/UnixEThread.cc:322
#18 0x000000000073a7a9 in spawn_thread_internal (a=0x2ba4e6682340) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/Thread.cc:92
#19 0x00002ba4e4a27dd5 in start_thread () from /lib64/libpthread.so.0
#20 0x00002ba4e575cead in clone () from /lib64/libc.so.6

or

(gdb) bt
#0  0x00002b3aa3ec7207 in raise () from /lib64/libc.so.6
#1  0x00002b3aa3ec88f8 in abort () from /lib64/libc.so.6
#2  0x00002b3aa162698b in ink_abort (message_format=message_format@entry=0x2b3aa16914e7 "%s:%d: failed assertion `%s`") at ../../../../../../_vcs/trafficserver9/src/tscore/ink_error.cc:99
#3  0x00002b3aa1624145 in _ink_assert (expression=expression@entry=0x741298 "!mutex || mutex->thread_holding == this_ethread()", 
    file=file@entry=0x7411e8 "/sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/build/../../../../_vcs/trafficserver9/iocore/eventsystem/I_Continuation.h", line=line@entry=166) at ../../../../../../_vcs/trafficserver9/src/tscore/ink_assert.cc:37
#4  0x00000000006f8d95 in handleEvent (data=0x2b3d4b1bf5d0, event=105, this=0x2b3d413d30b0)
    at /sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/build/../../../../_vcs/trafficserver9/include/tscore/ink_thread.h:124
#5  read_signal_and_update (event=105, vc=0x2b3d4b1bf400) at ../../../../../../_vcs/trafficserver9/iocore/net/UnixNetVConnection.cc:83
#6  0x00000000006fd30c in UnixNetVConnection::mainEvent(int, Event*) () at ../../../../../../_vcs/trafficserver9/iocore/net/UnixNetVConnection.cc:1152
#7  0x00000000006f0f0d in handleEvent (data=0x2b3aa4ffb9e0, event=105, this=0x2b3d4b1bf400)
    at /sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/build/../../../../_vcs/trafficserver9/iocore/eventsystem/I_Continuation.h:167
#8  handleEvent (data=0x2b3aa4ffb9e0, event=105, this=0x2b3d4b1bf400)
    at /sd/workspace/src/git.ouroath.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9/build/../../../../_vcs/trafficserver9/iocore/eventsystem/I_Continuation.h:163
#9  InactivityCop::check_inactivity (this=0x2b3ab2ac3000, event=<optimized out>, e=<optimized out>) at ../../../../../../_vcs/trafficserver9/iocore/net/UnixNet.cc:81
#10 0x000000000073b1f7 in handleEvent (data=0x2b3aa4ffb9e0, event=2, this=0x2b3ab2ac3000) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/I_Continuation.h:167
#11 handleEvent (data=0x2b3aa4ffb9e0, event=2, this=0x2b3ab2ac3000) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/I_Continuation.h:163
#12 EThread::process_event(Event*, int) () at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/UnixEThread.cc:136
#13 0x000000000073c084 in EThread::execute_regular (this=this@entry=0x2b3aa8f1ae00) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/UnixEThread.cc:249
#14 0x000000000073c4a6 in execute (this=0x2b3aa8f1ae00) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/UnixEThread.cc:344
#15 EThread::execute (this=0x2b3aa8f1ae00) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/UnixEThread.cc:322
#16 0x000000000073a7a9 in spawn_thread_internal (a=0x2b3aa4e82980) at ../../../../../../_vcs/trafficserver9/iocore/eventsystem/Thread.cc:92
#17 0x00002b3aa3259dd5 in start_thread () from /lib64/libpthread.so.0
#18 0x00002b3aa3f8eead in clone () from /lib64/libc.so.6

[zwoop]

Cool! Yes, this was one of a handful of PRs on the short list we were testing as well. Verifying on Docs right now, ideally we'll find a fix for it, but if we don't in the next few days, I'll revert this from 9.0.x as well.

[shinrich]

@masaori335 asked on channel whether the unix vc was inbound or outbound. It was outbound, which seems odd that this commit would have anything to do with it. I put the original sync build back into rotation and no crash after an hour. So I am far less certain this commit has anything to do with it. Evidently I was just very lucky (or unlucky) when I first tried the build and got 6 cores in 30 minutes.

I will set up another machine in the same colo with the reverted build and continue to fish for crashes.

[zwoop]

I'm running with it reverted right now on Docs, I started a git bisect (which is a really slow process for me on Docs), and I narrowed it down to the following range:

* ddb59564a Cleaned up indentation etc.
* f4623de40 Fixes a few Sphinx build warnings (#6290)
* 2f1c8f5fb Fixes typos and wrong ref
* 97975584b Removes the remaining references to TSQA
* a01608e9e Updated CHANGELOG
* 567b7558c Remove never implemented regex descriptions
* 63c1dd355 Updated Docs
* d810d66a8 auto delete rolled log file fixes
* 0cb00040f Adding verify plugin TS maintenance commands
* 7f57d01cb Enhance Connection Collapse in ATS core
* dac14897b Avoid unnecesarry copy on POST request over HTTP/2
* 06907caeb Fix TS_USE_DIAGS usage for --disable-diags option
* bdcd21f4a Fixes various crashers loading/reloading parent.config
* 6f125c1d4 Change HTTP/2 error rate log to warning
* c9edddd3d LGTM: Fix wrong type of arguments to formatting function
* 56b9cf0e9 LGTM: Add header guards
* 0a10b9854 Set END_STREAM flag when write_vio ntodo is 0
* 9e463b33e Fix sni.yaml fqdn to match complete name string
* d692908fe Updated ChangeLog
* 863e59a29 TCL: cleanup in HostLookup.cc, make sure keys are stable. (#6263)

[shinrich]

Finally got some results on my side-by-side comparison this morning. The machine with commit dac1489 crashed 11 times in an hour or os. It's peer running an image without this commit did not crash.

In the 4 cores I looked at, the inactive VC was outbound. The read vio pointed at a stale (reallocated) HttpSM with a buf pointer and ndone/nbytes set to 0. One of the cores the vc was not ssl. The others were SSL. One of the SSL's had the ssl_name set to a domain that servers a lot of POST requests. But given the activity of the machine and the difference of our active and inactive timeouts, I cannot tie to crashing VC to any particular access log entry. I'm assuming it is a result of a client aborted POST request, which we have plenty of.

[masaori335]

It looks like Http1ServerSession::release() nor Http1ServerSession::do_io_close were not called when HttpSM was freed. But I haven't found such path & no idea of how the commit is related.

[masaori335]

This is kind of random idea, how about replacing MUTEX_TRY_LOCK with SCOPED_MUTEX_LOCK like this? https://gist.github.com/masaori335/2e118a164c275e6139a7be08d4543f6d

[shinrich]

Will give it a try. Could well be that this commit just affects timing to reveal latent issue. In PR #6344 we did see cases where some of the close paths were not working as we expected. Need to get the tests resolved there to push that along. It could be added that fix will allow this commit to be happy.