ASAN heap-use-after-free in HttpVCTable::remove_entry

[zwoop]

As of recently I get

==5918==ERROR: AddressSanitizer: heap-use-after-free on address 0x6190000fca50 at pc 0x00000069683d bp 0x2b4311cee210 sp 0x2b4311cee200
READ of size 8 at 0x6190000fca50 thread T6 ([ET_NET 4])
    #0 0x69683c in HttpVCTable::remove_entry(HttpVCTableEntry*) /usr/local/src/trafficserver/proxy/http/HttpSM.cc:197
    #1 0x6de279 in HttpVCTable::cleanup_entry(HttpVCTableEntry*) /usr/local/src/trafficserver/proxy/http/HttpSM.cc:249
    #2 0x6de279 in HttpVCTable::cleanup_all() /usr/local/src/trafficserver/proxy/http/HttpSM.cc:257
    #3 0x6de279 in HttpSM::kill_this() /usr/local/src/trafficserver/proxy/http/HttpSM.cc:6815
    #4 0x6dfa97 in HttpSM::main_handler(int, void*) /usr/local/src/trafficserver/proxy/http/HttpSM.cc:2603
    #5 0x7f97cb in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
    #6 0x7f97cb in HttpTunnel::main_handler(int, void*) /usr/local/src/trafficserver/proxy/http/HttpTunnel.cc:1575
    #7 0xdfde70 in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
    #8 0xdfde70 in read_signal_and_update /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:83
    #9 0xdfde70 in read_signal_done /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:144
    #10 0xe10189 in read_from_net /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:279
    #11 0xdc9caa in NetHandler::process_ready_list() /usr/local/src/trafficserver/iocore/net/UnixNet.cc:396
    #12 0xdca8b8 in NetHandler::waitForActivity(long) /usr/local/src/trafficserver/iocore/net/UnixNet.cc:529
    #13 0xf26031 in EThread::execute_regular() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:277
    #14 0xf269c1 in EThread::execute() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:338
    #15 0xf20c6a in spawn_thread_internal /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:92
    #16 0x2b430b989dd4 in start_thread (/lib64/libpthread.so.0+0x7dd4)
    #17 0x2b430c6beeac in __clone (/lib64/libc.so.6+0xfdeac)

0x6190000fca50 is located 464 bytes inside of 1104-byte region [0x6190000fc880,0x6190000fccd0)
freed by thread T6 ([ET_NET 4]) here:
    #0 0x2b43090d3508 in __interceptor_free (/lib64/libasan.so.4+0xde508)
    #1 0x2b430a0c85dc in ink_freelist_free /usr/local/src/trafficserver/src/tscore/ink_queue.cc:277
    #2 0xdc938d in NetHandler::free_netvc(UnixNetVConnection*) /usr/local/src/trafficserver/iocore/net/UnixNet.cc:348
    #3 0xd629bd in SSLNetVConnection::do_io_close(int) /usr/local/src/trafficserver/iocore/net/SSLNetVConnection.cc:882
    #4 0x6433d0 in Http1ClientSession::do_io_close(int) /usr/local/src/trafficserver/proxy/http/Http1ClientSession.cc:283
    #5 0x7f05d6 in HttpTunnel::chain_abort_all(HttpTunnelProducer*) /usr/local/src/trafficserver/proxy/http/HttpTunnel.cc:1375
    #6 0x698b02 in HttpSM::tunnel_handler_server(int, HttpTunnelProducer*) /usr/local/src/trafficserver/proxy/http/HttpSM.cc:2954
    #7 0x7efab7 in HttpTunnel::producer_handler(int, HttpTunnelProducer*) /usr/local/src/trafficserver/proxy/http/HttpTunnel.cc:1168
    #8 0x7f9581 in HttpTunnel::main_handler(int, void*) /usr/local/src/trafficserver/proxy/http/HttpTunnel.cc:1556
    #9 0xdfde70 in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
    #10 0xdfde70 in read_signal_and_update /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:83
    #11 0xdfde70 in read_signal_done /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:144
    #12 0xe10189 in read_from_net /usr/local/src/trafficserver/iocore/net/UnixNetVConnection.cc:279
    #13 0xdc9caa in NetHandler::process_ready_list() /usr/local/src/trafficserver/iocore/net/UnixNet.cc:396
    #14 0xdca8b8 in NetHandler::waitForActivity(long) /usr/local/src/trafficserver/iocore/net/UnixNet.cc:529
    #15 0xf26031 in EThread::execute_regular() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:277
    #16 0xf269c1 in EThread::execute() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:338
    #17 0xf20c6a in spawn_thread_internal /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:92
    #18 0x2b430b989dd4 in start_thread (/lib64/libpthread.so.0+0x7dd4)

previously allocated by thread T23 ([ACCEPT 0:443]) here:
    #0 0x2b43090d44f0 in posix_memalign (/lib64/libasan.so.4+0xdf4f0)
    #1 0x2b430a0c64af in ats_memalign /usr/local/src/trafficserver/src/tscore/ink_memory.cc:102
    #2 0x2b430a0c853e in ink_freelist_new /usr/local/src/trafficserver/src/tscore/ink_queue.cc:187
    #3 0xd5317f in ClassAllocator<SSLNetVConnection>::alloc() ../../include/tscore/Allocator.h:131
    #4 0xd5317f in SSLNetProcessor::allocate_vc(EThread*) /usr/local/src/trafficserver/iocore/net/SSLNetProcessor.cc:106
    #5 0xde4580 in NetAccept::do_blocking_accept(EThread*) /usr/local/src/trafficserver/iocore/net/UnixNetAccept.cc:310
    #6 0xde6bca in NetAccept::acceptLoopEvent(int, Event*) /usr/local/src/trafficserver/iocore/net/UnixNetAccept.cc:519
    #7 0xf2661b in Continuation::handleEvent(int, void*) /usr/local/src/trafficserver/iocore/eventsystem/I_Continuation.h:190
    #8 0xf2661b in EThread::execute() /usr/local/src/trafficserver/iocore/eventsystem/UnixEThread.cc:322
    #9 0xf20c6a in spawn_thread_internal /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:92
    #10 0x2b430b989dd4 in start_thread (/lib64/libpthread.so.0+0x7dd4)

Thread T6 ([ET_NET 4]) created by T0 ([TS_MAIN]) here:
    #0 0x2b430902ca7f in pthread_create (/lib64/libasan.so.4+0x37a7f)
    #1 0xf21ede in ink_thread_create ../../include/tscore/ink_thread.h:159
    #2 0xf21ede in Thread::start(char const*, void*, unsigned long, std::function<void ()> const&) /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:109
    #3 0xf2fe7f in EventProcessor::spawn_event_threads(int, int, unsigned long) /usr/local/src/trafficserver/iocore/eventsystem/UnixEventProcessor.cc:382
    #4 0xf30f05 in EventProcessor::start(int, unsigned long) /usr/local/src/trafficserver/iocore/eventsystem/UnixEventProcessor.cc:448
    #5 0x4be9b6 in main traffic_server/traffic_server.cc:1838
    #6 0x2b430c5e33d4 in __libc_start_main (/lib64/libc.so.6+0x223d4)

Thread T23 ([ACCEPT 0:443]) created by T0 ([TS_MAIN]) here:
    #0 0x2b430902ca7f in pthread_create (/lib64/libasan.so.4+0x37a7f)
    #1 0xf21ede in ink_thread_create ../../include/tscore/ink_thread.h:159
    #2 0xf21ede in Thread::start(char const*, void*, unsigned long, std::function<void ()> const&) /usr/local/src/trafficserver/iocore/eventsystem/Thread.cc:109
    #3 0xf321bf in EventProcessor::spawn_thread(Continuation*, char const*, unsigned long) /usr/local/src/trafficserver/iocore/eventsystem/UnixEventProcessor.cc:490
    #4 0xdde369 in NetAccept::init_accept_loop() /usr/local/src/trafficserver/iocore/net/UnixNetAccept.cc:170
    #5 0xdef7c2 in UnixNetProcessor::accept_internal(Continuation*, int, NetProcessor::AcceptOptions const&) /usr/local/src/trafficserver/iocore/net/UnixNetProcessor.cc:141
    #6 0xdeb511 in NetProcessor::main_accept(Continuation*, int, NetProcessor::AcceptOptions const&) /usr/local/src/trafficserver/iocore/net/UnixNetProcessor.cc:86
    #7 0x68af0b in start_HttpProxyServer() /usr/local/src/trafficserver/proxy/http/HttpProxyServerMain.cc:338
    #8 0x4c057e in main traffic_server/traffic_server.cc:1969
    #9 0x2b430c5e33d4 in __libc_start_main (/lib64/libc.so.6+0x223d4)

SUMMARY: AddressSanitizer: heap-use-after-free /usr/local/src/trafficserver/proxy/http/HttpSM.cc:197 in HttpVCTable::remove_entry(HttpVCTableEntry*)
Shadow bytes around the buggy address:
  0x0c32800178f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c3280017900: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c3280017910: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c3280017920: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c3280017930: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
=>0x0c3280017940: fd fd fd fd fd fd fd fd fd fd[fd]fd fd fd fd fd
  0x0c3280017950: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c3280017960: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c3280017970: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c3280017980: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c3280017990: fd fd fd fd fd fd fd fd fd fd 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
==5918==ABORTING

[shinrich]

We had seen that in production too. Removed the cleanup logic since it does introduce a possibility for accessing a VC that has been previously deleted. Wanted to run it locally for a whiel to ensure that that it did not add a lot a dangling IO operators, and it has not.
Will put up a PR

[zwoop]

This also happens on 9.0.x branch, FYI. Do we know what PR started causing this?

Blocks #5457

[zwoop]

Happened 29 times on Docs, since last time I restarted. I guess I'll start git bisecting.

[zwoop]

Looking at the timing, I worry now that this might be related to the massive merge of quic-latest branch -> master ? @maskit @masaori335 I understand that this is not directly in QUIC code, but is it possible some refactoring here is causing this ?

[masaori335]

Do we know what PR started causing this?

Probably, #4020. As @bryancall pointed out on #5809 (fix for this crash), it looks reverting part of #4020.

[zwoop]

Been running with #5809 on Docs for a couple of days, no more ASAN reports. We good to go with that fix?