Get ClientRespHeader failed in TSHttpTxnClose Hook

[zhangqiang-01]

When I get ClientRespHeader statistics for response code at TSHttpTxnClose hook, but i find TSHttpTxnClientRespGet return false。

ats version: 7.1.8

g_txn_close_contp = TSContCreate(MetricsTxnCloseHookHandle, nullptr);
TSHttpHookAdd(TS_HTTP_TXN_CLOSE_HOOK, g_txn_close_contp);

static int
MetricsTxnCloseHookHandle(TSCont /* contp ATS_UNUSED */, TSEvent event, void *edata)
{
  .....
  status = HttpStatusGet(txnp);
  .....
}

static TSHttpStatus
HttpStatusGet(TSHttpTxn txnp)
{
  TSHttpStatus status;
  TSMBuffer req_bufp;
  TSMLoc req_loc;
  TSAssert(TSHttpTxnClientRespGet(txnp, &req_bufp, &req_loc) == TS_SUCCESS);
  status = TSHttpHdrStatusGet(req_bufp, req_loc);
  TSHandleMLocRelease(req_bufp, TS_NULL_MLOC, req_loc);
  return status;
}

Carsh Stack:

(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007f1ea232b51a in __GI_abort () at abort.c:118
#2  0x00007f1ea49a413b in ink_abort (message_format=message_format@entry=0x7f1ea49b0927 "%s:%d: failed assertion `%s`")
    at ink_error.cc:99
#3  0x00007f1ea49a2465 in _ink_assert (
    expression=expression@entry=0x55f4fab5e848 "sdk_sanity_check_mbuffer(bufp) == TS_SUCCESS", 
    file=file@entry=0x55f4fab5e580 "InkAPI.cc", line=line@entry=3913) at ink_assert.cc:37
#4  0x000055f4fa845a31 in _TSReleaseAssert (line=3913, file=0x55f4fab5e580 "InkAPI.cc", 
    text=0x55f4fab5e848 "sdk_sanity_check_mbuffer(bufp) == TS_SUCCESS") at InkAPI.cc:396
#5  TSHttpHdrStatusGet (bufp=<optimized out>, obj=<optimized out>) at InkAPI.cc:3913
#6  0x00007f1e943ef646 in HttpStatusGet (txnp=0x7f1b06589000) at src/ats_metrics.cc:31
#7  MetricsTxnCloseHookHandle (event=<optimized out>, edata=0x7f1b06589000) at src/ats_metrics.cc:186
#8  0x000055f4fa83ec12 in INKContInternal::handle_event (this=0x7f1ea0bfba80, event=60012, edata=0x7f1b06589000)
    at InkAPI.cc:1044
#9  0x000055f4fa91c59e in HttpSM::state_api_callout (this=this@entry=0x7f1b06589000, event=event@entry=60000, 
    data=data@entry=0x0) at HttpSM.cc:1448
#10 0x000055f4fa9264e2 in HttpSM::state_api_callback (this=this@entry=0x7f1b06589000, event=event@entry=60000, 
    data=data@entry=0x0) at HttpSM.cc:1321
#11 0x000055f4fa854798 in TSHttpTxnReenable (txnp=0x7f1b06589000, event=TS_EVENT_HTTP_CONTINUE) at InkAPI.cc:5894
#12 0x00007f1e943ede77 in PluginInitHandleHook (event=<optimized out>, edata=0x7f1b06589000) at src/plugin_init.cc:88
#13 0x000055f4fa83ec12 in INKContInternal::handle_event (this=0x7f1ea0bfb8a0, event=60012, edata=0x7f1b06589000)
    at InkAPI.cc:1044
#14 0x000055f4fa91c59e in HttpSM::state_api_callout (this=0x7f1b06589000, event=<optimized out>, data=<optimized out>)
    at HttpSM.cc:1448
#15 0x000055f4fa925634 in HttpSM::kill_this (this=0x7f1b06589000) at HttpSM.cc:6926
#16 0x000055f4fa92630c in HttpSM::attach_client_session (this=<optimized out>, 
    client_vc=client_vc@entry=0x7f15d886c1e8, buffer_reader=<optimized out>) at HttpSM.cc:620
#17 0x000055f4fa87d51a in ProxyClientTransaction::new_transaction (this=this@entry=0x7f15d886c1e8)
    at ProxyClientTransaction.cc:60
#18 0x000055f4fa901960 in Http1ClientSession::new_transaction (this=0x7f15d886bf00) at Http1ClientSession.cc:507
#19 Http1ClientSession::release (trans=0x7f15d886c1e8, this=0x7f15d886bf00) at Http1ClientSession.cc:471
#20 Http1ClientSession::start (this=0x7f15d886bf00) at Http1ClientSession.h:65
#21 0x000055f4fa87c8be in ProxyClientSession::handle_api_return (this=0x7f15d886bf00, event=<optimized out>)
    at ProxyClientSession.cc:204
#22 0x000055f4fa87c96f in ProxyClientSession::state_api_callout (this=0x7f15d886bf00, event=<optimized out>, 
    data=<optimized out>) at ProxyClientSession.cc:160
#23 0x000055f4fa8544b3 in Continuation::handleEvent (data=0x0, event=60000, this=0x7f15d886bf00)
    at /data/bdcdn_open_soft/soft/source/trafficserver-7.1.8/iocore/eventsystem/I_Continuation.h:152
#24 TSHttpSsnReenable (ssnp=0x7f15d886bf00, event=TS_EVENT_HTTP_CONTINUE) at InkAPI.cc:4603
---Type <return> to continue, or q <return> to quit---
#25 0x00007f1e943ee3e7 in MetricsSsnStartHookHandle (event=<optimized out>, edata=0x7f15d886bf00)
    at src/ats_metrics.cc:41
#26 0x000055f4fa83ec12 in INKContInternal::handle_event (this=0x7f1ea0bfb900, event=60013, edata=0x7f15d886bf00)
    at InkAPI.cc:1044
#27 0x000055f4fa87ca2f in ProxyClientSession::state_api_callout (this=this@entry=0x7f15d886bf00, event=event@entry=0, 
    data=data@entry=0x0) at ProxyClientSession.cc:146
#28 0x000055f4fa87ce1b in ProxyClientSession::do_api_callout (this=this@entry=0x7f15d886bf00, 
    id=id@entry=TS_HTTP_SSN_START_HOOK) at ProxyClientSession.cc:182
#29 0x000055f4fa8fd9de in Http1ClientSession::new_connection (this=0x7f15d886bf00, new_vc=<optimized out>, 
    iobuf=<optimized out>, reader=<optimized out>, backdoor=<optimized out>) at Http1ClientSession.cc:219
#30 0x000055f4fa8f7da4 in HttpSessionAccept::accept (this=0x7f1e9738c000, netvc=0x7f04b9e69b00, iobuf=0x7f1e9685e700, 
    reader=0x7f1e9685e718) at HttpSessionAccept.cc:72
#31 0x000055f4fa87c230 in ProtocolProbeTrampoline::ioCompletionEvent (this=0x7f102ea7a000, event=<optimized out>, 
    edata=<optimized out>) at ProtocolProbeSessionAccept.cc:107
#32 0x000055f4fab1cb8a in Continuation::handleEvent (data=0x7f04b9e69c30, event=100, this=<optimized out>)
    at /data/bdcdn_open_soft/soft/source/trafficserver-7.1.8/iocore/eventsystem/I_Continuation.h:152
#33 read_signal_and_update (vc=0x7f04b9e69b00, event=100) at UnixNetVConnection.cc:144
#34 read_from_net (nh=<optimized out>, vc=0x7f04b9e69b00, thread=<optimized out>) at UnixNetVConnection.cc:384
#35 0x000055f4fab0dbee in NetHandler::waitForActivity (this=0x7f1e9f0c7c00, timeout=<optimized out>) at UnixNet.cc:497
#36 0x000055f4fab58112 in EThread::execute_regular (this=0x7f1e9f0c3d40) at UnixEThread.cc:248
#37 0x000055f4fab56519 in spawn_thread_internal (a=0x7f1ea1f482f0) at Thread.cc:84
#38 0x00007f1ea313e4a4 in start_thread (arg=0x7f1e9d706700) at pthread_create.c:456
#39 0x00007f1ea23dfd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

[zhangqiang-01]

I'm not sure why this problem， even if the request and response are problematic, ats should respond correctly.

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had recent activity. Marking it stale to flag it for further consideration by the community.

[ywkaras]

Did this happen in an optimized or a debug build? In an optimized build, TSAssert() is optimized out, so TSHttpTxnClientRespGet may have returned TS_ERROR. I don't think ClientRestGet will always return TS_SUCCESS in the close hook unless you are adding the continuation in the SEND_RESPONSE_HDR hook. Have you seen this problem in ATS9?

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had recent activity. Marking it stale to flag it for further consideration by the community.

[Pheewww]

@bryancall can i work on this?

One possible cause of this error is that the client response header has already been released or is not available for some reason. To address this issue, you can add a check to ensure that the client response header is available before trying to retrieve it.

Another possible cause of this error is that the TSHttpTxnClose hook is being called after the client response has already been closed. In this case, you may need to move the hook to an earlier point in the transaction flow where the client response header is still available.