9.1 assertion in TSHandleMLocRelease

[shinrich]

After running solidly all weekend, I had a bunch of repeated asserts with the following stack from our production box running 9.1.x. The stack looks weird because the invoking plugin is written in Lua. (as a side note if anyone know how to get symbols from lua plugins I would appreciate any hints).

#0  0x00002b8d28cbe3d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:55
#1  0x00002b8d28cbfac8 in __GI_abort () at abort.c:90
#2  0x00002b8d2621861b in ink_abort (message_format=message_format@entry=0x2b8d2623ac27 "%s:%d: failed assertion `%s`")
    at ../../../../../../_vcs/trafficserver9.1/src/tscore/ink_error.cc:99
#3  0x00002b8d26214b95 in _ink_assert (expression=expression@entry=0x7efd82 "!\"invalid mloc\"", 
    file=file@entry=0x7edf30 "../../../../../_vcs/trafficserver9.1/src/traffic_server/InkAPI.cc", line=line@entry=2117)
    at ../../../../../../_vcs/trafficserver9.1/src/tscore/ink_assert.cc:37
#4  0x0000000000505d90 in TSHandleMLocRelease (bufp=0x2b8f904f3828, parent=<optimized out>, mloc=0x2b8f59d54308) at ../../../../../_vcs/trafficserver9.1/src/traffic_server/InkAPI.cc:2117
#5  0x00002b8f3a719748 in ?? ()
#6  0x00002b8f904f3000 in ?? ()
#7  0x00002b8f904f3828 in ?? ()
#8  0x00002b8f59d54088 in ?? ()
#9  0x00002b8f59d54308 in ?? ()
#10 0x00002b8d31bfeedc in ?? ()
#11 0x00002b8f4ddc8120 in ?? ()
#12 0x00002b8f376da840 in ?? ()
#13 0x00002b8f904f3000 in ?? ()
#14 0x000000000000ea64 in ?? ()
#15 0x0000000000502f00 in INKContInternal::handle_event(int, void*) () at ../../../../../_vcs/trafficserver9.1/src/traffic_server/InkAPI.cc:1137
#16 0x0000000000517037 in handleEvent (data=0x2b8f904f3000, event=60004, this=0x2b8f4ddc8120)
    at /sd/workspace/src/git.vzbuilders.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_vcs/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#17 handleEvent (data=0x2b8f904f3000, event=60004, this=0x2b8f4ddc8120)
    at /sd/workspace/src/git.vzbuilders.com/Edge/build/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_vcs/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#18 APIHook::invoke(int, void*) const () at ../../../../../_vcs/trafficserver9.1/src/traffic_server/InkAPI.cc:1374

Specifically it assert is in the default case and the obj->m_type == 0, which implies that mloc has already been freed or had never been allocated.

TSReturnCode
TSHandleMLocRelease(TSMBuffer bufp, TSMLoc parent, TSMLoc mloc)
{
  MIMEFieldSDKHandle *field_handle;
  HdrHeapObjImpl *obj = (HdrHeapObjImpl *)mloc;

  if (mloc == TS_NULL_MLOC) {
    return TS_SUCCESS;
  }

  sdk_assert(sdk_sanity_check_mbuffer(bufp) == TS_SUCCESS);

  switch (obj->m_type) {
  case HDR_HEAP_OBJ_URL:
  case HDR_HEAP_OBJ_HTTP_HEADER:
  case HDR_HEAP_OBJ_MIME_HEADER:
    return TS_SUCCESS;

  case HDR_HEAP_OBJ_FIELD_SDK_HANDLE:
    field_handle = (MIMEFieldSDKHandle *)obj;
    if (sdk_sanity_check_field_handle(mloc, parent) != TS_SUCCESS) {
      return TS_ERROR;
    }

    sdk_free_field_handle(bufp, field_handle);
    return TS_SUCCESS;

  default:
    ink_release_assert(!"invalid mloc");
    return TS_ERROR;
  }
}

We did not see this assert in our 9.0.x branch. Adding HDR_HEAP_OBJ_EMPTY to the success cases, the assert goes away and things seem to run well, but would be good to understand the change in behavior.

[shinrich]

In the MLoc object, the m_type was 0 and the m_length was 112 which corresponds to a URL object

(gdb) print sizeof(URLImpl)
$3 = 112

[ywkaras]

How can you tell it's the Lua plugin?

[shinrich]

That is my assumption because their is no information on the stack. Based on past experience where the top of stack pops out into lua logging, that empty stack corresponds to the a lua plugin.

[shinrich]

I have removed all the calls to TSHandleMLocRelease for the URL references from the lua plugin and I still get the assert. It is possible that one of our plugins is being built without symbols.

[shinrich]

With the plugin symbols loaded the top of stack looks like this, pointing a finger at the s3_auth plugin.

(gdb) bt
#0  0x00002b55c13eb3d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:55
#1  0x00002b55c13ecac8 in __GI_abort () at abort.c:90
#2  0x00002b55be94561b in ink_abort (message_format=message_format@entry=0x2b55be967c47 "%s:%d: failed assertion `%s`") at ../../../../../../_vcs/trafficserver9.1/src/tscore/ink_error.cc:99
#3  0x00002b55be941b95 in _ink_assert (expression=expression@entry=0x7f135a "!\"invalid mloc\"", file=file@entry=0x7ef508 "../../../../../_vcs/trafficserver9.1/src/traffic_server/InkAPI.cc", 
    line=line@entry=2117) at ../../../../../../_vcs/trafficserver9.1/src/tscore/ink_assert.cc:37
#4  0x0000000000505d80 in TSHandleMLocRelease (bufp=0x2b583c7f4828, parent=<optimized out>, mloc=0x2b583c690308) at ../../../../../_vcs/trafficserver9.1/src/traffic_server/InkAPI.cc:2117
#5  0x00002b57d307f6e8 in ~S3Request (this=0x2b55c586fae0, __in_chrg=<optimized out>) at ../../../../../_vcs/trafficserver9.1/plugins/s3_auth/s3_auth.cc:1027
#6  event_handler (cont=<optimized out>, event=<optimized out>, edata=0x2b583c7f4000) at ../../../../../_vcs/trafficserver9.1/plugins/s3_auth/s3_auth.cc:997
#7  0x0000000000502ef0 in INKContInternal::handle_event(int, void*) () at ../../../../../_vcs/trafficserver9.1/src/traffic_server/InkAPI.cc:1137
#8  0x0000000000517117 in handleEvent (data=0x2b583c7f4000, event=60004, this=0x2b57e5977080)
    at /home/shinrich/build-91/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_vcs/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#9  handleEvent (data=0x2b583c7f4000, event=60004, this=0x2b57e5977080)
    at /home/shinrich/build-91/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_vcs/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#10 APIHook::invoke(int, void*) const () at ../../../../../_vcs/trafficserver9.1/src/traffic_server/InkAPI.cc:1374
#11 0x000000000057ddd7 in HttpSM::state_api_callout(int, void*) () at ../../../../../../_vcs/trafficserver9.1/proxy/http/HttpSM.cc:1551

[ywkaras]

The object that's created here, https://github.com/apache/trafficserver/blame/master/plugins/s3_auth/s3_auth.cc#L997 , will not be destroyed until after TSHttpTxnReenable() is called. The destructor calls TSHandleMLocRelease(). Is that kosher? This looks like it's been in there for years, so I don't know why it would wait till now to break.