search

apache / trafficserver

Apache Traffic Server™ is a fast, scalable and extensible HTTP/1.1 and HTTP/2 compliant caching proxy server.
https://trafficserver.apache.org/
Apache License 2.0
1.8k stars 798 forks source link

ASan: heap-use-after-free with RegressionTest_SDK_API_HttpTxnTransform #11796

Open masaori335 opened 2 days ago

masaori335 commented 2 days ago

Intermittently, I faced this ASan report on my mac.

$ while /opt/ats-asf-master-asan/bin/traffic_server -K -k -R 1; do done
...
REGRESSION TEST SDK_API_HttpTxnTransform started
Regression test(SDK_API_HttpTxnTransform) still in progress
[SDK_API_HttpTxnTransform] TSTransformCreate : [TestCase1] <<PASS>> { ok }
[SDK_API_HttpTxnTransform] TSHttpTxnTransformRespGet : [TestCase] <<PASS>> { ok }
[SDK_API_HttpTxnTransform] TSHttpTxnTransformRespGet : [TestCase] <<PASS>> { ok }
[SDK_API_HttpTxnTransform] TSHttpTxnTransformRespGet : [TestCase] <<PASS>> { ok }
=================================================================
==94062==ERROR: AddressSanitizer: heap-use-after-free on address 0x61200008f044 at pc 0x0001015435e8 bp 0x00010794b6a0 sp 0x00010794b698
WRITE of size 4 at 0x61200008f044 thread T10
    #0 0x1015435e4 in UnixSocket::close() UnixSocket.cc:137
    #1 0x1023f8b50 in synserver_delete(SocketServer*) InkAPITest.cc:865
    #2 0x1023f0060 in transform_hook_handler(tsapi_cont*, TSEvent, void*) InkAPITest.cc:8047
    #3 0x1015918ec in INKContInternal::handle_event(int, void*) InkContInternal.cc:153
    #4 0x101534504 in EThread::process_event(Event*, int) UnixEThread.cc:163
    #5 0x101536650 in EThread::execute_regular() UnixEThread.cc:270
    #6 0x101537ba4 in EThread::execute() UnixEThread.cc:350
    #7 0x101531d98 in spawn_thread_internal(void*) Thread.cc
    #8 0x10337f2d0 in asan_thread_start(void*)+0x48 (libclang_rt.asan_osx_dynamic.dylib:arm64+0x4f2d0)
    #9 0x192e7b2e0 in _pthread_start+0x84 (libsystem_pthread.dylib:arm64+0x72e0)
    #10 0x192e760f8 in thread_start+0x4 (libsystem_pthread.dylib:arm64+0x20f8)

0x61200008f044 is located 132 bytes inside of 296-byte region [0x61200008efc0,0x61200008f0e8)
freed by thread T7 here:
    #0 0x103391454 in _ZdlPv+0x6c (libclang_rt.asan_osx_dynamic.dylib:arm64+0x61454)
    #1 0x1014b96ac in NetAccept::acceptEvent(int, void*) UnixNetAccept.cc
    #2 0x101534504 in EThread::process_event(Event*, int) UnixEThread.cc:163
    #3 0x101536900 in EThread::execute_regular() UnixEThread.cc:281
    #4 0x101537ba4 in EThread::execute() UnixEThread.cc:350
    #5 0x101531d98 in spawn_thread_internal(void*) Thread.cc
    #6 0x10337f2d0 in asan_thread_start(void*)+0x48 (libclang_rt.asan_osx_dynamic.dylib:arm64+0x4f2d0)
    #7 0x192e7b2e0 in _pthread_start+0x84 (libsystem_pthread.dylib:arm64+0x72e0)
    #8 0x192e760f8 in thread_start+0x4 (libsystem_pthread.dylib:arm64+0x20f8)

previously allocated by thread T10 here:
    #0 0x10339103c in _Znwm+0x6c (libclang_rt.asan_osx_dynamic.dylib:arm64+0x6103c)
    #1 0x1014c04bc in UnixNetProcessor::createNetAccept(AcceptOptions const&) UnixNetProcessor.cc:295
    #2 0x1014bc95c in UnixNetProcessor::accept_internal(Continuation*, int, AcceptOptions const&) UnixNetProcessor.cc:86
    #3 0x1023a0114 in TSNetAccept(tsapi_cont*, int, int, int) InkAPI.cc:6077
    #4 0x1023e22f0 in synserver_start(SocketServer*) InkAPITest.cc:841
    #5 0x1023ef7d8 in RegressionTest_SDK_API_HttpTxnTransform(RegressionTest*, int, int*) InkAPITest.cc:8169
    #6 0x100e407f0 in RegressionTest::run_some(int) Regression.cc:156
    #7 0x100e40cec in RegressionTest::check_status(int) Regression.cc:173
    #8 0x100e0f534 in RegressionCont::mainEvent(int, Event*) traffic_server.cc:1568
    #9 0x101534504 in EThread::process_event(Event*, int) UnixEThread.cc:163
    #10 0x101536650 in EThread::execute_regular() UnixEThread.cc:270
    #11 0x101537ba4 in EThread::execute() UnixEThread.cc:350
    #12 0x101531d98 in spawn_thread_internal(void*) Thread.cc
    #13 0x10337f2d0 in asan_thread_start(void*)+0x48 (libclang_rt.asan_osx_dynamic.dylib:arm64+0x4f2d0)
    #14 0x192e7b2e0 in _pthread_start+0x84 (libsystem_pthread.dylib:arm64+0x72e0)
    #15 0x192e760f8 in thread_start+0x4 (libsystem_pthread.dylib:arm64+0x20f8)

Thread T10 created by T0 here:
    #0 0x10337a068 in pthread_create+0x58 (libclang_rt.asan_osx_dynamic.dylib:arm64+0x4a068)
    #1 0x101531b6c in Thread::start(char const*, void*, unsigned long, std::__1::function<void ()> const&) Thread.cc:92
    #2 0x10153f688 in EventProcessor::spawn_event_threads(int, int, unsigned long) UnixEventProcessor.cc:469
    #3 0x101540a68 in EventProcessor::start(int, unsigned long) UnixEventProcessor.cc:550
    #4 0x100dfeb7c in main traffic_server.cc:2110
    #5 0x192af8270  (<unknown module>)

Thread T7 created by T0 here:
    #0 0x10337a068 in pthread_create+0x58 (libclang_rt.asan_osx_dynamic.dylib:arm64+0x4a068)
    #1 0x101531b6c in Thread::start(char const*, void*, unsigned long, std::__1::function<void ()> const&) Thread.cc:92
    #2 0x10153f688 in EventProcessor::spawn_event_threads(int, int, unsigned long) UnixEventProcessor.cc:469
    #3 0x101540a68 in EventProcessor::start(int, unsigned long) UnixEventProcessor.cc:550
    #4 0x100dfeb7c in main traffic_server.cc:2110
    #5 0x192af8270  (<unknown module>)

SUMMARY: AddressSanitizer: heap-use-after-free UnixSocket.cc:137 in UnixSocket::close()
Shadow bytes around the buggy address:
  0x61200008ed80: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fa fa
  0x61200008ee00: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
  0x61200008ee80: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x61200008ef00: fd fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa
  0x61200008ef80: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
=>0x61200008f000: fd fd fd fd fd fd fd fd[fd]fd fd fd fd fd fd fd
  0x61200008f080: fd fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa
  0x61200008f100: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x61200008f180: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x61200008f200: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x61200008f280: 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
==94062==ABORTING
traffic_server: received signal 6 (Abort trap: 6)
traffic_server - STACK TRACE:
0   traffic_server                      0x0000000100ded224 _Z19crash_logger_invokeiP9__siginfoPv + 296
1   libsystem_platform.dylib            0x0000000192eb0184 _sigtramp + 56
2   libsystem_pthread.dylib             0x0000000192e7af70 pthread_kill + 288
3   libsystem_c.dylib                   0x0000000192d87908 abort + 128
4   libclang_rt.asan_osx_dynamic.dylib  0x00000001033a7380 _ZN11__sanitizer6AtexitEPFvvE + 0
5   libclang_rt.asan_osx_dynamic.dylib  0x00000001033a6ae8 _ZN11__sanitizer22SetCheckUnwindCallbackEPFvvE + 0
6   libclang_rt.asan_osx_dynamic.dylib  0x000000010338a548 _ZN6__asan16ErrorDescription5PrintEv + 0
7   libclang_rt.asan_osx_dynamic.dylib  0x00000001033898ec _ZN6__asan18ReportGenericErrorEmmmmbmjb + 1956
8   libclang_rt.asan_osx_dynamic.dylib  0x000000010338ae68 __asan_report_store4 + 52
9   traffic_server                      0x00000001015435e8 _ZN10UnixSocket5closeEv + 292
10  libtsapi.dylib                      0x00000001023f8b54 _ZL16synserver_deleteP12SocketServer + 848
11  libtsapi.dylib                      0x00000001023f0064 _ZL22transform_hook_handlerP10tsapi_cont7TSEventPv + 984
12  traffic_server                      0x00000001015918f0 _ZN15INKContInternal12handle_eventEiPv + 464
13  traffic_server                      0x0000000101534508 _ZN7EThread13process_eventEP5Eventi + 1840
14  traffic_server                      0x0000000101536654 _ZN7EThread15execute_regularEv + 1908
15  traffic_server                      0x0000000101537ba8 _ZN7EThread7executeEv + 1112
16  traffic_server                      0x0000000101531d9c _ZL21spawn_thread_internalPv + 220
17  libclang_rt.asan_osx_dynamic.dylib  0x000000010337f2d4 _ZL17asan_thread_startPv + 76
18  libsystem_pthread.dylib             0x0000000192e7b2e4 _pthread_start + 136
19  libsystem_pthread.dylib             0x0000000192e760fc thread_start + 8
masaori335 commented 2 days ago

Another report from SDK_API_HttpHookAdd

[SDK_API_HttpHookAdd] TSHttpTxnReenable : [TestCase1] <<PASS>> { ok }
=================================================================
==31721==ERROR: AddressSanitizer: heap-use-after-free on address 0x61200008f344 at pc 0x0001055a284c bp 0x00010bad3600 sp 0x00010bad35f8
WRITE of size 4 at 0x61200008f344 thread T10
    #0 0x1055a2848 in UnixSocket::close() UnixSocket.cc:137
    #1 0x1064802dc in synserver_delete(SocketServer*) InkAPITest.cc:865
    #2 0x106467a54 in mytest_handler(tsapi_cont*, TSEvent, void*) InkAPITest.cc:3584
    #3 0x1055f1068 in INKContInternal::handle_event(int, void*) InkContInternal.cc:153
    #4 0x105593768 in EThread::process_event(Event*, int) UnixEThread.cc:163
    #5 0x1055958b4 in EThread::execute_regular() UnixEThread.cc:270
    #6 0x105596e08 in EThread::execute() UnixEThread.cc:350
    #7 0x105590ffc in spawn_thread_internal(void*) Thread.cc
    #8 0x10740b2d0 in asan_thread_start(void*)+0x48 (libclang_rt.asan_osx_dynamic.dylib:arm64+0x4f2d0)
    #9 0x192e7b2e0 in _pthread_start+0x84 (libsystem_pthread.dylib:arm64+0x72e0)
    #10 0x192e760f8 in thread_start+0x4 (libsystem_pthread.dylib:arm64+0x20f8)

0x61200008f344 is located 132 bytes inside of 296-byte region [0x61200008f2c0,0x61200008f3e8)
freed by thread T16 here:
    #0 0x10741d454 in _ZdlPv+0x6c (libclang_rt.asan_osx_dynamic.dylib:arm64+0x61454)
    #1 0x105518910 in NetAccept::acceptEvent(int, void*) UnixNetAccept.cc
    #2 0x105593768 in EThread::process_event(Event*, int) UnixEThread.cc:163
    #3 0x105595b64 in EThread::execute_regular() UnixEThread.cc:281
    #4 0x105596e08 in EThread::execute() UnixEThread.cc:350
    #5 0x105590ffc in spawn_thread_internal(void*) Thread.cc
    #6 0x10740b2d0 in asan_thread_start(void*)+0x48 (libclang_rt.asan_osx_dynamic.dylib:arm64+0x4f2d0)
    #7 0x192e7b2e0 in _pthread_start+0x84 (libsystem_pthread.dylib:arm64+0x72e0)
    #8 0x192e760f8 in thread_start+0x4 (libsystem_pthread.dylib:arm64+0x20f8)

previously allocated by thread T10 here:
    #0 0x10741d03c in _Znwm+0x6c (libclang_rt.asan_osx_dynamic.dylib:arm64+0x6103c)
    #1 0x10551f720 in UnixNetProcessor::createNetAccept(AcceptOptions const&) UnixNetProcessor.cc:295
    #2 0x10551bbc0 in UnixNetProcessor::accept_internal(Continuation*, int, AcceptOptions const&) UnixNetProcessor.cc:86
    #3 0x106426010 in TSNetAccept(tsapi_cont*, int, int, int) InkAPI.cc:6077
    #4 0x106469a7c in synserver_start(SocketServer*) InkAPITest.cc:841
    #5 0x106466e08 in RegressionTest_SDK_API_HttpHookAdd(RegressionTest*, int, int*) InkAPITest.cc:3638
    #6 0x104e9b550 in RegressionTest::run_some(int) Regression.cc:156
    #7 0x104e9ba4c in RegressionTest::check_status(int) Regression.cc:173
    #8 0x104e6a7c4 in RegressionCont::mainEvent(int, Event*) traffic_server.cc:1568
    #9 0x105593768 in EThread::process_event(Event*, int) UnixEThread.cc:163
    #10 0x1055958b4 in EThread::execute_regular() UnixEThread.cc:270
    #11 0x105596e08 in EThread::execute() UnixEThread.cc:350
    #12 0x105590ffc in spawn_thread_internal(void*) Thread.cc
    #13 0x10740b2d0 in asan_thread_start(void*)+0x48 (libclang_rt.asan_osx_dynamic.dylib:arm64+0x4f2d0)
    #14 0x192e7b2e0 in _pthread_start+0x84 (libsystem_pthread.dylib:arm64+0x72e0)
    #15 0x192e760f8 in thread_start+0x4 (libsystem_pthread.dylib:arm64+0x20f8)

Thread T10 created by T0 here:
    #0 0x107406068 in pthread_create+0x58 (libclang_rt.asan_osx_dynamic.dylib:arm64+0x4a068)
    #1 0x105590dd0 in Thread::start(char const*, void*, unsigned long, std::__1::function<void ()> const&) Thread.cc:92
    #2 0x10559e8ec in EventProcessor::spawn_event_threads(int, int, unsigned long) UnixEventProcessor.cc:469
    #3 0x10559fccc in EventProcessor::start(int, unsigned long) UnixEventProcessor.cc:550
    #4 0x104e5804c in main traffic_server.cc:2110
    #5 0x192af8270  (<unknown module>)

Thread T16 created by T0 here:
    #0 0x107406068 in pthread_create+0x58 (libclang_rt.asan_osx_dynamic.dylib:arm64+0x4a068)
    #1 0x105590dd0 in Thread::start(char const*, void*, unsigned long, std::__1::function<void ()> const&) Thread.cc:92
    #2 0x10559e8ec in EventProcessor::spawn_event_threads(int, int, unsigned long) UnixEventProcessor.cc:469
    #3 0x10559fccc in EventProcessor::start(int, unsigned long) UnixEventProcessor.cc:550
    #4 0x104e5804c in main traffic_server.cc:2110
    #5 0x192af8270  (<unknown module>)

SUMMARY: AddressSanitizer: heap-use-after-free UnixSocket.cc:137 in UnixSocket::close()
Shadow bytes around the buggy address:
  0x61200008f080: fd fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa
  0x61200008f100: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
  0x61200008f180: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x61200008f200: fd fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa
  0x61200008f280: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
=>0x61200008f300: fd fd fd fd fd fd fd fd[fd]fd fd fd fd fd fd fd
  0x61200008f380: fd fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa
  0x61200008f400: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x61200008f480: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x61200008f500: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x61200008f580: 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
==31721==ABORTING
traffic_server: received signal 6 (Abort trap: 6)
traffic_server - STACK TRACE:
0   traffic_server                      0x0000000104e46568 _Z19crash_logger_invokeiP9__siginfoPv + 296
1   libsystem_platform.dylib            0x0000000192eb0184 _sigtramp + 56
2   libsystem_pthread.dylib             0x0000000192e7af70 pthread_kill + 288
3   libsystem_c.dylib                   0x0000000192d87908 abort + 128
4   libclang_rt.asan_osx_dynamic.dylib  0x0000000107433380 _ZN11__sanitizer6AtexitEPFvvE + 0
5   libclang_rt.asan_osx_dynamic.dylib  0x0000000107432ae8 _ZN11__sanitizer22SetCheckUnwindCallbackEPFvvE + 0
6   libclang_rt.asan_osx_dynamic.dylib  0x0000000107416548 _ZN6__asan16ErrorDescription5PrintEv + 0
7   libclang_rt.asan_osx_dynamic.dylib  0x00000001074158ec _ZN6__asan18ReportGenericErrorEmmmmbmjb + 1956
8   libclang_rt.asan_osx_dynamic.dylib  0x0000000107416e68 __asan_report_store4 + 52
9   traffic_server                      0x00000001055a284c _ZN10UnixSocket5closeEv + 292
10  libtsapi.dylib                      0x00000001064802e0 _ZL16synserver_deleteP12SocketServer + 848
11  libtsapi.dylib                      0x0000000106467a58 _ZL14mytest_handlerP10tsapi_cont7TSEventPv + 2740
12  traffic_server                      0x00000001055f106c _ZN15INKContInternal12handle_eventEiPv + 464
13  traffic_server                      0x000000010559376c _ZN7EThread13process_eventEP5Eventi + 1840
14  traffic_server                      0x00000001055958b8 _ZN7EThread15execute_regularEv + 1908
15  traffic_server                      0x0000000105596e0c _ZN7EThread7executeEv + 1112
16  traffic_server                      0x0000000105591000 _ZL21spawn_thread_internalPv + 220
17  libclang_rt.asan_osx_dynamic.dylib  0x000000010740b2d4 _ZL17asan_thread_startPv + 76
18  libsystem_pthread.dylib             0x0000000192e7b2e4 _pthread_start + 136
19  libsystem_pthread.dylib             0x0000000192e760fc thread_start + 8
masaori335 commented 2 days ago

There must be a race of canceling actions.

https://github.com/apache/trafficserver/blob/dac1ab1f196731ce8d193c7444857b64394b2552/src/iocore/eventsystem/UnixSocket.cc#L137

https://github.com/apache/trafficserver/blob/dac1ab1f196731ce8d193c7444857b64394b2552/src/iocore/net/UnixNetAccept.cc#L473

However, it looks like an issue of the synthetic server only used by this InkAPITest Regression test.