8.1.1 Memory Leak on following redirect

[masaori335]

We observed a memory leak on 8.1.1. This happens only on parent nodes. We don't see the leak on child nodes.

We're trying to narrow down which commit is making the leak. The current list is below.

c71b08269 (tag: 8.1.1-rc0) Updated ChangeLog and STATUS
ac7ed9580 Add negative caching tests and fixes. (#7359)
0960ef5b8 ESI: Ensure gzip header is always initialized (#7358)
c080cc1ec Updated ChangeLog
dc7b8691c Sticky server does not work with H2 client (#7261) (#7297)
5ce3c75ed Fix truncated reponse on HTTP/2 graceful shutdown (#7267)
12953fc5e Updated ChangeLog
4d0f3e356 Updated ChangeLog
867c0a858 Update HttpTransact.cc
ab73c83d3 add support for centos8 (#7268)
581ce8679 Updated ChangeLog
5494225b4 Replace existing autest certs with ones from master. These are considered insecure by more recent versions of openssl and will fail to load (#7244)
24bca0378 Updated ChangeLog
043ba6ee8  Do not cache Transfer-Encoding header (#7234)
3eab13563 slice: check if vio is still valid before calling TSVIODone* on shutdown (#7147)
6ec727fdc slice: fix throttle not work (#7008) (#7195)
f972a70a1 Updated ChangeLog
9c55701f3 Remove usage of stored ACL record, always pull from current ipallow (#7217)
502ee35dd Updated ChangeLog
f78b4e0b0 Emits log when OCSP fails to connect to server (#7183) (#7191)
d0ad15b05 Updated ChangeLog
fff68b0cc Fixes garbled logs when using %<vbn> log tag (#7156)
503d8930d Updated ChangeLog
5621853a7 Fixes H2 toggling using ssl_server_name.yaml (#7154)
887f2bb0d Bumped version for builds etc. to v8.1.1
72c03baa8 Updated STATUS
c802ae02d Disable lua_stats autest until we can reliably wait for stats

[masaori335]

I was tackling down #7379, ASan detected a leak on my local box. This seems related to the leak on our production.
If I revert ac7ed9580, this leak is gone.

ASan report (8.1.1)

Direct leak of 256 byte(s) in 1 object(s) allocated from:                                                                                                                             #0 0x10a9ebbb3 in wrap_posix_memalign+0xb3 (libclang_rt.asan_osx_dynamic.dylib:x86_64+0x46bb3)
    #1 0x10a12f1d9 in ats_memalign ink_memory.cc:102
    #2 0x10a160ff1 in jearena::JemallocNodumpAllocator::allocate(_InkFreeList*) JeAllocator.cc:118
    #3 0x10a1356e9 in malloc_new(_InkFreeList*) ink_queue.cc:269
    #4 0x10a131127 in ink_freelist_new ink_queue.cc:192
    #5 0x108faf9df in ClassAllocator<HTTPCacheAlt>::alloc() Allocator.h:133
    #6 0x108faf90f in HTTPInfo::create() HTTP.cc:1969
    #7 0x108d7a83b in HttpTransact::handle_cache_operation_on_forward_server_response(HttpTransact::State*) HttpTransact.cc:4269
    #8 0x108d70903 in HttpTransact::handle_forward_server_connection_open(HttpTransact::State*) HttpTransact.cc:3850
    #9 0x108d69335 in HttpTransact::handle_response_from_server(HttpTransact::State*) HttpTransact.cc:3498
    #10 0x108d2c124 in HttpTransact::HandleResponse(HttpTransact::State*) HttpTransact.cc:3200
    #11 0x108c51906 in HttpSM::call_transact_and_set_next_state(void (*)(HttpTransact::State*)) HttpSM.cc:7161
    #12 0x108c6ca00 in HttpSM::handle_api_return() HttpSM.cc:1590
    #13 0x108c6a9d6 in HttpSM::state_api_callout(int, void*) HttpSM.cc:1525
    #14 0x108cb78e9 in HttpSM::do_api_callout_internal() HttpSM.cc:5103
    #15 0x108c464ac in HttpSM::do_api_callout() HttpSM.cc:340
    #16 0x108c809c5 in HttpSM::state_read_server_response_header(int, void*) HttpSM.cc:1945
    #17 0x108c4539c in HttpSM::main_handler(int, void*) HttpSM.cc:2558
    #18 0x108af3b57 in Continuation::handleEvent(int, void*) I_Continuation.h:160
    #19 0x1093a05b8 in read_signal_and_update(int, UnixNetVConnection*) UnixNetVConnection.cc:83
    #20 0x10939e2dc in read_from_net(NetHandler*, UnixNetVConnection*, EThread*) UnixNetVConnection.cc:327
    #21 0x10939c6e4 in UnixNetVConnection::net_read_io(NetHandler*, EThread*) UnixNetVConnection.cc:916
    #22 0x10936e0e0 in NetHandler::process_ready_list() UnixNet.cc:399
    #23 0x109370469 in NetHandler::waitForActivity(long long) UnixNet.cc:532
    #24 0x10941895b in EThread::execute_regular() UnixEThread.cc:278
    #25 0x109419b74 in EThread::execute() UnixEThread.cc:331
    #26 0x1094142ef in spawn_thread_internal(void*) Thread.cc:85
    #27 0x7fff2036c94f in _pthread_start+0xdf (libsystem_pthread.dylib:x86_64+0x694f)
    #28 0x7fff2036847a in thread_start+0xe (libsystem_pthread.dylib:x86_64+0x247a)

Repro

Origin: httpbin on port 8001

ATS

CONFIG proxy.config.http.negative_caching_enabled INT 1
CONFIG proxy.config.http.number_of_redirections INT 1

# if ATS is 9.0.x and later
#CONFIG proxy.config.http.redirect.actions STRING self:follow

Client

curl -vsk --http1.1 "http://localhost:8080/httpbin/redirect-to?status_code=302&url=http%3A%2F%2Flocalhost%3A8001%2F" -o /dev/null

[masaori335]

When the number_of_redirections is more than 1 and the negative cache is enabled, the transaction comes into line 4469 twice. The HTTPCacheAlt, which allocated on the first call, leaks because it's not freed before the second call of HTTPInfo::create().

trafficserver/proxy/http/HttpTransact.cc

Lines 4467 to 4469 in 95d1069

	if (s->is_cacheable_and_negative_caching_is_enabled) {
	HTTPHdr *resp;
	s->cache_info.object_store.create();

Moreover, the master & 9.0.x has the same issue.

Steps on LLDB (click to expand)

#
# the first call
#
Process 91536 stopped
* thread #5, name = '[ET_NET 3]', stop reason = breakpoint 1.1
    frame #0: 0x0000000100388f78 traffic_server`HttpTransact::handle_cache_operation_on_forward_server_response(s=0x0000625000020a08) at HttpTransact.cc:4469:9
   4466         s->cache_info.action == CACHE_DO_REPLACE) {
   4467       if (s->is_cacheable_and_negative_caching_is_enabled) {
   4468         HTTPHdr *resp;
-> 4469         s->cache_info.object_store.create();
   4470         s->cache_info.object_store.request_set(&s->hdr_info.client_request);
   4471         s->cache_info.object_store.response_set(&s->hdr_info.server_response);
   4472         resp = s->cache_info.object_store.response_get();
(lldb) p s->cache_info.object_store
(HTTPInfo) $0 = {
  m_alt = 0x0000000000000000
}
(lldb) n
Process 91536 stopped
* thread #5, name = '[ET_NET 3]', stop reason = step over
    frame #0: 0x0000000100388f93 traffic_server`HttpTransact::handle_cache_operation_on_forward_server_response(s=0x0000625000020a08) at HttpTransact.cc:4470:9
   4467       if (s->is_cacheable_and_negative_caching_is_enabled) {
   4468         HTTPHdr *resp;
   4469         s->cache_info.object_store.create();
-> 4470         s->cache_info.object_store.request_set(&s->hdr_info.client_request);
   4471         s->cache_info.object_store.response_set(&s->hdr_info.server_response);
   4472         resp = s->cache_info.object_store.response_get();
   4473         if (!resp->presence(MIME_PRESENCE_EXPIRES)) {
(lldb) p s->cache_info.object_store
(HTTPInfo) $1 = {
  m_alt = 0x0000612000030040
}
#
# the second call
#
Process 91536 stopped
* thread #5, name = '[ET_NET 3]', stop reason = breakpoint 1.1
    frame #0: 0x0000000100388f78 traffic_server`HttpTransact::handle_cache_operation_on_forward_server_response(s=0x0000625000020a08) at HttpTransact.cc:4469:9
   4466         s->cache_info.action == CACHE_DO_REPLACE) {
   4467       if (s->is_cacheable_and_negative_caching_is_enabled) {
   4468         HTTPHdr *resp;
-> 4469         s->cache_info.object_store.create();
   4470         s->cache_info.object_store.request_set(&s->hdr_info.client_request);
   4471         s->cache_info.object_store.response_set(&s->hdr_info.server_response);
   4472         resp = s->cache_info.object_store.response_get();
(lldb) p s->cache_info.object_store
(HTTPInfo) $2 = {
  m_alt = 0x0000612000030040
}
(lldb) n
Process 91536 stopped
* thread #5, name = '[ET_NET 3]', stop reason = step over
    frame #0: 0x0000000100388f93 traffic_server`HttpTransact::handle_cache_operation_on_forward_server_response(s=0x0000625000020a08) at HttpTransact.cc:4470:9
   4467       if (s->is_cacheable_and_negative_caching_is_enabled) {
   4468         HTTPHdr *resp;
   4469         s->cache_info.object_store.create();
-> 4470         s->cache_info.object_store.request_set(&s->hdr_info.client_request);
   4471         s->cache_info.object_store.response_set(&s->hdr_info.server_response);
   4472         resp = s->cache_info.object_store.response_get();
   4473         if (!resp->presence(MIME_PRESENCE_EXPIRES)) {
(lldb) p s->cache_info.object_store
(HTTPInfo) $3 = {
  m_alt = 0x00006120000301c0
}

[bneradt]

Good observations.

When the number_of_redirections is more than 1 and the negative cache is enabled, the transaction comes into line 4469 twice. The HTTPCacheAlt, which allocated on the first call, leaks because it's not freed before the second call of HTTPInfo::create().

trafficserver/proxy/http/HttpTransact.cc

Lines 4467 to 4469 in 95d1069

	if (s->is_cacheable_and_negative_caching_is_enabled) {
	HTTPHdr *resp;
	s->cache_info.object_store.create();

I need to spend some time thinking through how the negative caching fix introduced this. It's not obvious to me from the patch. Is it your observation that the negative caching fix reveals this because now, rather than being served incorrectly from the cache, the redirect is followed?

Moreover, the master & 9.0.x has the same issue.

To be complete: that change also went into 7.x as well via: #7357

[masaori335]

Is it your observation that the negative caching fix reveals this because now, rather than being served incorrectly from the cache, the redirect is followed?

The redirect is followed. The first call comes from 302 responses and the second call comes from 200 responses. This is why we're seeing the leak only with following redirections.

[bneradt]

Considering @masaori335 's observations, I've been looking at the code and reviewing the negative caching patch and I do notice a change that the negative caching fix did that I didn't anticipate. Here was the code that @masaori335 referenced before fix:

trafficserver/proxy/http/HttpTransact.cc

Line 4505 in f364761

if (s->negative_caching) {

Before the patch, the value of negative_caching was true iff the response was cacheable because of negative caching configuration. That is, a 200 response would not cause it to be true: only negative status codes that were considered cacheable because negative caching was enabled would have caused negative_caching to be evaluated to true. With the patch, the cacheable variable was changed to reflect negative caching configuration to make it clearer. In so doing, I had to recode the evaluation of negative_caching. I attempted to keep the value the same while renaming it to is_cacheable_and_negative_caching_is_enabled to clarify its intent. In doing so, I missed that the previous nature of negative_caching was to be false for positive status codes. Therefore it doesn't behave the same and the branch @masaori335 references now behaves differently, being followed in cases it wouldn't have before. That sounds to me very likely the cause of the problem he's reporting.

The fix will be to adjust the evaluation of is_cacheable_and_negative_caching_is_enabled to match the previous behavior of negative_caching.

I'll work with @masaori335 on a patch for this and verify whether this fixes the leak he's seeing.

Thank you @masaori335 for the detailed observations.

[bneradt]

I'm closing this since @masaori335 observed that the patch in #7401, now merged, resolved this leak. Re-open if that turns out not to fix this issue.