You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafficserver.apache.org by "Luca Bruno (JIRA)" <ji...@apache.org> on 2015/03/19 13:20:38 UTC
[jira] [Updated] (TS-3455) Renaming Cache-Control in read-response
and marking the cache STALE in lookup-complete causes abort()
[ https://issues.apache.org/jira/browse/TS-3455?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Luca Bruno updated TS-3455:
---------------------------
Description:
I've written a simple test case plugin for demonstrating this problem, not sure if it's a problem on my side.
What the plugin does:
1) In READ_RESPONSE_HDR rename Cache-Control to X-Plugin-Cache-Control
2) In LOOKUP_COMPLETE, if it's a FRESH hit set the status to be STALE instead
So after the cache has been enabled, do a first request: this will be cached because there's no Cache-Control header.
Do a second request, now ATS will abort().
The issue is related to both the fact that Cache-Control is renamed and the cache set to be stale. Either of the two alone don't trigger the issue.
Plugin code:
{noformat}
#include <ts/ts.h>
#include <ts/remap.h>
#include <ts/experimental.h>
#include <stdlib.h>
#include <stdio.h>
#include <getopt.h>
#include <string.h>
#include <string>
#include <iterator>
#include <map>
// Constants and some declarations
const char PLUGIN_NAME[] = "maybebug";
static int Handler(TSCont cont, TSEvent event, void *edata);
struct PluginState {
PluginState()
{
cont = TSContCreate(Handler, NULL);
TSContDataSet(cont, this);
}
~PluginState()
{
TSContDestroy(cont);
}
TSCont cont;
};
static int Handler(TSCont cont, TSEvent event, void* edata) {
TSHttpTxn txn = (TSHttpTxn)edata;
TSMBuffer mbuf;
TSMLoc hdrp;
if (event == TS_EVENT_HTTP_READ_RESPONSE_HDR) {
TSDebug(PLUGIN_NAME, "read response");
if (TS_SUCCESS == TSHttpTxnServerRespGet(txn, &mbuf, &hdrp)) {
TSMLoc fieldp = TSMimeHdrFieldFind(mbuf, hdrp, "Cache-Control", sizeof("Cache-Control")-1);
if (fieldp != TS_NULL_MLOC) {
TSDebug(PLUGIN_NAME, "rename cache-control");
TSMimeHdrFieldNameSet(mbuf, hdrp, fieldp, "X-Plugin-Cache-Control", sizeof("X-Plugin-Cache-Control")-1);
TSHandleMLocRelease(mbuf, hdrp, fieldp);
}
TSHandleMLocRelease(mbuf, TS_NULL_MLOC, hdrp);
}
} else if (event == TS_EVENT_HTTP_CACHE_LOOKUP_COMPLETE) {
int lookup_status;
if (TS_SUCCESS != TSHttpTxnCacheLookupStatusGet(txn, &lookup_status)) {
goto beach;
}
TSDebug(PLUGIN_NAME, "lookup complete: %d", lookup_status);
if (lookup_status == TS_CACHE_LOOKUP_HIT_FRESH && TSHttpTxnCachedRespGet(txn, &mbuf, &hdrp) == TS_SUCCESS) {
TSMLoc fieldp = TSMimeHdrFieldFind(mbuf, hdrp, "X-Plugin-Cache-Control", sizeof("X-Plugin-Cache-Control")-1);
if (fieldp) {
TSDebug(PLUGIN_NAME, "set stale");
TSHandleMLocRelease(mbuf, hdrp, fieldp);
TSHttpTxnCacheLookupStatusSet(txn, TS_CACHE_LOOKUP_HIT_STALE);
}
TSHandleMLocRelease(mbuf, TS_NULL_MLOC, hdrp);
}
}
beach:
TSHttpTxnReenable(txn, TS_EVENT_HTTP_CONTINUE);
return TS_EVENT_NONE;
}
TSReturnCode TSRemapInit(TSRemapInterface* api, char* errbuf, int bufsz) {
return TS_SUCCESS;
}
TSReturnCode TSRemapNewInstance(int argc, char* argv[], void** instance, char* errbuf, int errbuf_size) {
TSDebug(PLUGIN_NAME, "new instance");
PluginState* es = new PluginState();
*instance = es;
return TS_SUCCESS;
}
void TSRemapDeleteInstance(void* instance) {
delete static_cast<PluginState*>(instance);
}
TSRemapStatus TSRemapDoRemap(void* instance, TSHttpTxn txn, TSRemapRequestInfo* rri) {
PluginState* es = static_cast<PluginState*>(instance);
TSHttpTxnHookAdd(txn, TS_HTTP_READ_RESPONSE_HDR_HOOK, es->cont);
TSHttpTxnHookAdd(txn, TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK, es->cont);
return TSREMAP_NO_REMAP;
}
{noformat}
Stacktrace from gdb:
{noformat}
#1 0x00007ffff54e53e0 in abort () from /lib/x86_64-linux-gnu/libc.so.6
#2 0x00007ffff7bb96fc in ink_die_die_die (retval=1) at ink_error.cc:43
#3 0x00007ffff7bb97c2 in ink_fatal_va(int, const char *, typedef __va_list_tag __va_list_tag *) (return_code=1, fmt=0x7ffff7bca490 "%s:%d: failed assert `%s`", ap=0x7ffff42813d8)
at ink_error.cc:67
#4 0x00007ffff7bb986d in ink_fatal (return_code=1, message_format=0x7ffff7bca490 "%s:%d: failed assert `%s`") at ink_error.cc:75
#5 0x00007ffff7bb73a0 in _ink_assert (expression=0x7c6883 "s->pending_work == NULL", file=0x7c66cc "HttpTransact.cc", line=433) at ink_assert.cc:37
#6 0x000000000060d0aa in how_to_open_connection (s=0x7fffdacac9d0) at HttpTransact.cc:433
#7 0x0000000000619206 in HttpTransact::HandleCacheOpenReadHit (s=0x7fffdacac9d0) at HttpTransact.cc:2684
#8 0x00000000005ffd21 in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6954
#9 0x00000000005ebc20 in HttpSM::handle_api_return (this=0x7fffdacac960) at HttpSM.cc:1532
#10 0x00000000005eb9d5 in HttpSM::state_api_callout (this=0x7fffdacac960, event=0, data=0x0) at HttpSM.cc:1464
#11 0x00000000005f8bcb in HttpSM::do_api_callout_internal (this=0x7fffdacac960) at HttpSM.cc:4912
#12 0x0000000000606999 in HttpSM::do_api_callout (this=0x7fffdacac960) at HttpSM.cc:450
#13 0x00000000005ffed0 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:6996
#14 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6962
#15 0x00000000005f5378 in HttpSM::do_hostdb_lookup (this=0x7fffdacac960) at HttpSM.cc:4043
#16 0x0000000000600874 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:7092
#17 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6962
#18 0x00000000005ebc20 in HttpSM::handle_api_return (this=0x7fffdacac960) at HttpSM.cc:1532
#19 0x00000000005eb9d5 in HttpSM::state_api_callout (this=0x7fffdacac960, event=60000, data=0x0) at HttpSM.cc:1464
#20 0x00000000005eb0dc in HttpSM::state_api_callback (this=0x7fffdacac960, event=60000, data=0x0) at HttpSM.cc:1282
#21 0x0000000000531919 in TSHttpTxnReenable (txnp=0x7fffdacac960, event=TS_EVENT_HTTP_CONTINUE) at InkAPI.cc:5577
#22 0x00007fffef64a0cc in Handler (cont=0x1315040, event=TS_EVENT_HTTP_CACHE_LOOKUP_COMPLETE, edata=0x7fffdacac960) at bug.cxx:68
#23 0x0000000000525ebf in INKContInternal::handle_event (this=0x1315040, event=60015, edata=0x7fffdacac960) at InkAPI.cc:1008
#24 0x00000000005112d4 in Continuation::handleEvent (this=0x1315040, event=60015, data=0x7fffdacac960) at ../iocore/eventsystem/I_Continuation.h:146
#25 0x00000000005267de in APIHook::invoke (this=0x1399eb0, event=60015, edata=0x7fffdacac960) at InkAPI.cc:1227
#26 0x00000000005eb764 in HttpSM::state_api_callout (this=0x7fffdacac960, event=0, data=0x0) at HttpSM.cc:1389
#27 0x00000000005f8bcb in HttpSM::do_api_callout_internal (this=0x7fffdacac960) at HttpSM.cc:4912
#28 0x0000000000606999 in HttpSM::do_api_callout (this=0x7fffdacac960) at HttpSM.cc:450
#29 0x00000000005ffed0 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:6996
#30 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6962
#31 0x00000000005ebc20 in HttpSM::handle_api_return (this=0x7fffdacac960) at HttpSM.cc:1532
#32 0x00000000005eb9d5 in HttpSM::state_api_callout (this=0x7fffdacac960, event=0, data=0x0) at HttpSM.cc:1464
#33 0x00000000005f8bcb in HttpSM::do_api_callout_internal (this=0x7fffdacac960) at HttpSM.cc:4912
#34 0x0000000000606999 in HttpSM::do_api_callout (this=0x7fffdacac960) at HttpSM.cc:450
#35 0x00000000005ffed0 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:6996
#36 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0x6162d2 <HttpTransact::HandleCacheOpenRead(HttpTransact::State*)>) at HttpSM.cc:6962
#37 0x00000000005ef48b in HttpSM::state_cache_open_read (this=0x7fffdacac960, event=1102, data=0x15ad510) at HttpSM.cc:2515
#38 0x00000000005ef9b8 in HttpSM::main_handler (this=0x7fffdacac960, event=1102, data=0x15ad510) at HttpSM.cc:2574
#39 0x00000000005112d4 in Continuation::handleEvent (this=0x7fffdacac960, event=1102, data=0x15ad510) at ../iocore/eventsystem/I_Continuation.h:146
#40 0x00000000005da01c in HttpCacheSM::state_cache_open_read (this=0x7fffdacae398, event=1102, data=0x15ad510) at HttpCacheSM.cc:118
#41 0x00000000005112d4 in Continuation::handleEvent (this=0x7fffdacae398, event=1102, data=0x15ad510) at ../iocore/eventsystem/I_Continuation.h:146
#42 0x000000000073686f in CacheVC::callcont (this=0x15ad510, event=1102) at P_CacheInternal.h:661
#43 0x00000000007349a9 in CacheVC::openReadStartEarliest (this=0x15ad510) at CacheRead.cc:955
#44 0x00000000005112d4 in Continuation::handleEvent (this=0x15ad510, event=3900, data=0x0) at ../iocore/eventsystem/I_Continuation.h:146
#45 0x0000000000713740 in CacheVC::handleReadDone (this=0x15ad510, event=3900, e=0x15ad698) at Cache.cc:2668
#46 0x00000000005112d4 in Continuation::handleEvent (this=0x15ad510, event=3900, data=0x15ad698) at ../iocore/eventsystem/I_Continuation.h:146
#47 0x0000000000718d11 in AIOCallbackInternal::io_complete (this=0x15ad698, event=1, data=0x1172c70) at ../../iocore/aio/P_AIO.h:124
#48 0x00000000005112d4 in Continuation::handleEvent (this=0x15ad698, event=1, data=0x1172c70) at ../iocore/eventsystem/I_Continuation.h:146
#49 0x000000000078ed3d in EThread::process_event (this=0x7ffff4688010, e=0x1172c70, calling_code=1) at UnixEThread.cc:144
#50 0x000000000078ef91 in EThread::execute (this=0x7ffff4688010) at UnixEThread.cc:195
#51 0x000000000078e272 in spawn_thread_internal (a=0x1130c40) at Thread.cc:88
#52 0x00007ffff6545b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#53 0x00007ffff558c7bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#54 0x0000000000000000 in ?? ()
{noformat}
Debug output from the plugin
{noformat}
[Mar 19 11:27:29.173] Server {0x2afb87afae00} DIAG: (maybebug) new instance
[Mar 19 11:29:39.786] Server {0x2afb88608700} DIAG: (maybebug) lookup complete: 1
[Mar 19 11:29:39.790] Server {0x2afb88608700} DIAG: (maybebug) read response
[Mar 19 11:29:40.240] Server {0x2afb88608700} DIAG: (maybebug) rename cache-control
[Mar 19 11:29:40.420] Server {0x2afb88507700} DIAG: (maybebug) lookup complete: 2
[Mar 19 11:29:40.420] Server {0x2afb88507700} DIAG: (maybebug) set stale
{noformat}
was:
I've written a simple test case plugin for demonstrating this problem, not sure if it's a problem on my side.
What the plugin does:
1) In READ_RESPONSE_HDR rename Cache-Control to X-Plugin-Cache-Control
2) In LOOKUP_COMPLETE, if it's a FRESH hit set the status to be STALE instead
So after the cache has been enabled, do a first request: this will be cached because there's no Cache-Control header.
Do a second request, now ATS will abort().
The issue is related to both the fact that Cache-Control is renamed and the cache set to be stale. Either of the two alone don't trigger the issue.
Plugin code:
{noformat}
#include <ts/ts.h>
#include <ts/remap.h>
#include <ts/experimental.h>
#include <stdlib.h>
#include <stdio.h>
#include <getopt.h>
#include <string.h>
#include <string>
#include <iterator>
#include <map>
// Constants and some declarations
const char PLUGIN_NAME[] = "maybebug";
static int Handler(TSCont cont, TSEvent event, void *edata);
struct PluginState {
PluginState()
{
cont = TSContCreate(Handler, NULL);
TSContDataSet(cont, this);
}
~PluginState()
{
TSContDestroy(cont);
}
TSCont cont;
};
static int Handler(TSCont cont, TSEvent event, void* edata) {
TSHttpTxn txn = (TSHttpTxn)edata;
TSMBuffer mbuf;
TSMLoc hdrp;
if (event == TS_EVENT_HTTP_READ_RESPONSE_HDR) {
TSDebug(PLUGIN_NAME, "read response");
if (TS_SUCCESS == TSHttpTxnServerRespGet(txn, &mbuf, &hdrp)) {
TSMLoc fieldp = TSMimeHdrFieldFind(mbuf, hdrp, "Cache-Control", sizeof("Cache-Control")-1);
if (fieldp != TS_NULL_MLOC) {
TSDebug(PLUGIN_NAME, "rename cache-control");
TSMimeHdrFieldNameSet(mbuf, hdrp, fieldp, "X-Plugin-Cache-Control", sizeof("X-Plugin-Cache-Control")-1);
TSHandleMLocRelease(mbuf, hdrp, fieldp);
}
TSHandleMLocRelease(mbuf, TS_NULL_MLOC, hdrp);
}
} else if (event == TS_EVENT_HTTP_CACHE_LOOKUP_COMPLETE) {
int lookup_status;
if (TS_SUCCESS != TSHttpTxnCacheLookupStatusGet(txn, &lookup_status)) {
goto beach;
}
TSDebug(PLUGIN_NAME, "lookup complete: %d", lookup_status);
if (lookup_status == TS_CACHE_LOOKUP_HIT_FRESH && TSHttpTxnCachedRespGet(txn, &mbuf, &hdrp) == TS_SUCCESS) {
TSMLoc fieldp = TSMimeHdrFieldFind(mbuf, hdrp, "X-Plugin-Cache-Control", sizeof("X-Plugin-Cache-Control")-1);
if (fieldp) {
TSDebug(PLUGIN_NAME, "set stale");
TSHandleMLocRelease(mbuf, hdrp, fieldp);
TSHttpTxnCacheLookupStatusSet(txn, TS_CACHE_LOOKUP_HIT_STALE);
}
TSHandleMLocRelease(mbuf, TS_NULL_MLOC, hdrp);
}
}
beach:
TSHttpTxnReenable(txn, TS_EVENT_HTTP_CONTINUE);
return TS_EVENT_NONE;
}
TSReturnCode TSRemapInit(TSRemapInterface* api, char* errbuf, int bufsz) {
return TS_SUCCESS;
}
TSReturnCode TSRemapNewInstance(int argc, char* argv[], void** instance, char* errbuf, int errbuf_size) {
TSDebug(PLUGIN_NAME, "new instance");
PluginState* es = new PluginState();
*instance = es;
return TS_SUCCESS;
}
void TSRemapDeleteInstance(void* instance) {
delete static_cast<PluginState*>(instance);
}
TSRemapStatus TSRemapDoRemap(void* instance, TSHttpTxn txn, TSRemapRequestInfo* rri) {
PluginState* es = static_cast<PluginState*>(instance);
TSHttpTxnHookAdd(txn, TS_HTTP_READ_RESPONSE_HDR_HOOK, es->cont);
TSHttpTxnHookAdd(txn, TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK, es->cont);
return TSREMAP_NO_REMAP;
}
{noformat}
Stacktrace from gdb:
{noformat}
#1 0x00007ffff54e53e0 in abort () from /lib/x86_64-linux-gnu/libc.so.6
#2 0x00007ffff7bb96fc in ink_die_die_die (retval=1) at ink_error.cc:43
#3 0x00007ffff7bb97c2 in ink_fatal_va(int, const char *, typedef __va_list_tag __va_list_tag *) (return_code=1, fmt=0x7ffff7bca490 "%s:%d: failed assert `%s`", ap=0x7ffff42813d8)
at ink_error.cc:67
#4 0x00007ffff7bb986d in ink_fatal (return_code=1, message_format=0x7ffff7bca490 "%s:%d: failed assert `%s`") at ink_error.cc:75
#5 0x00007ffff7bb73a0 in _ink_assert (expression=0x7c6883 "s->pending_work == NULL", file=0x7c66cc "HttpTransact.cc", line=433) at ink_assert.cc:37
#6 0x000000000060d0aa in how_to_open_connection (s=0x7fffdacac9d0) at HttpTransact.cc:433
#7 0x0000000000619206 in HttpTransact::HandleCacheOpenReadHit (s=0x7fffdacac9d0) at HttpTransact.cc:2684
#8 0x00000000005ffd21 in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6954
#9 0x00000000005ebc20 in HttpSM::handle_api_return (this=0x7fffdacac960) at HttpSM.cc:1532
#10 0x00000000005eb9d5 in HttpSM::state_api_callout (this=0x7fffdacac960, event=0, data=0x0) at HttpSM.cc:1464
#11 0x00000000005f8bcb in HttpSM::do_api_callout_internal (this=0x7fffdacac960) at HttpSM.cc:4912
#12 0x0000000000606999 in HttpSM::do_api_callout (this=0x7fffdacac960) at HttpSM.cc:450
#13 0x00000000005ffed0 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:6996
#14 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6962
#15 0x00000000005f5378 in HttpSM::do_hostdb_lookup (this=0x7fffdacac960) at HttpSM.cc:4043
#16 0x0000000000600874 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:7092
#17 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6962
#18 0x00000000005ebc20 in HttpSM::handle_api_return (this=0x7fffdacac960) at HttpSM.cc:1532
#19 0x00000000005eb9d5 in HttpSM::state_api_callout (this=0x7fffdacac960, event=60000, data=0x0) at HttpSM.cc:1464
#20 0x00000000005eb0dc in HttpSM::state_api_callback (this=0x7fffdacac960, event=60000, data=0x0) at HttpSM.cc:1282
#21 0x0000000000531919 in TSHttpTxnReenable (txnp=0x7fffdacac960, event=TS_EVENT_HTTP_CONTINUE) at InkAPI.cc:5577
#22 0x00007fffef64a0cc in Handler (cont=0x1315040, event=TS_EVENT_HTTP_CACHE_LOOKUP_COMPLETE, edata=0x7fffdacac960) at bug.cxx:68
#23 0x0000000000525ebf in INKContInternal::handle_event (this=0x1315040, event=60015, edata=0x7fffdacac960) at InkAPI.cc:1008
#24 0x00000000005112d4 in Continuation::handleEvent (this=0x1315040, event=60015, data=0x7fffdacac960) at ../iocore/eventsystem/I_Continuation.h:146
#25 0x00000000005267de in APIHook::invoke (this=0x1399eb0, event=60015, edata=0x7fffdacac960) at InkAPI.cc:1227
#26 0x00000000005eb764 in HttpSM::state_api_callout (this=0x7fffdacac960, event=0, data=0x0) at HttpSM.cc:1389
#27 0x00000000005f8bcb in HttpSM::do_api_callout_internal (this=0x7fffdacac960) at HttpSM.cc:4912
#28 0x0000000000606999 in HttpSM::do_api_callout (this=0x7fffdacac960) at HttpSM.cc:450
#29 0x00000000005ffed0 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:6996
#30 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6962
#31 0x00000000005ebc20 in HttpSM::handle_api_return (this=0x7fffdacac960) at HttpSM.cc:1532
#32 0x00000000005eb9d5 in HttpSM::state_api_callout (this=0x7fffdacac960, event=0, data=0x0) at HttpSM.cc:1464
#33 0x00000000005f8bcb in HttpSM::do_api_callout_internal (this=0x7fffdacac960) at HttpSM.cc:4912
#34 0x0000000000606999 in HttpSM::do_api_callout (this=0x7fffdacac960) at HttpSM.cc:450
#35 0x00000000005ffed0 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:6996
#36 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0x6162d2 <HttpTransact::HandleCacheOpenRead(HttpTransact::State*)>) at HttpSM.cc:6962
#37 0x00000000005ef48b in HttpSM::state_cache_open_read (this=0x7fffdacac960, event=1102, data=0x15ad510) at HttpSM.cc:2515
#38 0x00000000005ef9b8 in HttpSM::main_handler (this=0x7fffdacac960, event=1102, data=0x15ad510) at HttpSM.cc:2574
#39 0x00000000005112d4 in Continuation::handleEvent (this=0x7fffdacac960, event=1102, data=0x15ad510) at ../iocore/eventsystem/I_Continuation.h:146
#40 0x00000000005da01c in HttpCacheSM::state_cache_open_read (this=0x7fffdacae398, event=1102, data=0x15ad510) at HttpCacheSM.cc:118
#41 0x00000000005112d4 in Continuation::handleEvent (this=0x7fffdacae398, event=1102, data=0x15ad510) at ../iocore/eventsystem/I_Continuation.h:146
#42 0x000000000073686f in CacheVC::callcont (this=0x15ad510, event=1102) at P_CacheInternal.h:661
#43 0x00000000007349a9 in CacheVC::openReadStartEarliest (this=0x15ad510) at CacheRead.cc:955
#44 0x00000000005112d4 in Continuation::handleEvent (this=0x15ad510, event=3900, data=0x0) at ../iocore/eventsystem/I_Continuation.h:146
#45 0x0000000000713740 in CacheVC::handleReadDone (this=0x15ad510, event=3900, e=0x15ad698) at Cache.cc:2668
#46 0x00000000005112d4 in Continuation::handleEvent (this=0x15ad510, event=3900, data=0x15ad698) at ../iocore/eventsystem/I_Continuation.h:146
#47 0x0000000000718d11 in AIOCallbackInternal::io_complete (this=0x15ad698, event=1, data=0x1172c70) at ../../iocore/aio/P_AIO.h:124
#48 0x00000000005112d4 in Continuation::handleEvent (this=0x15ad698, event=1, data=0x1172c70) at ../iocore/eventsystem/I_Continuation.h:146
#49 0x000000000078ed3d in EThread::process_event (this=0x7ffff4688010, e=0x1172c70, calling_code=1) at UnixEThread.cc:144
#50 0x000000000078ef91 in EThread::execute (this=0x7ffff4688010) at UnixEThread.cc:195
#51 0x000000000078e272 in spawn_thread_internal (a=0x1130c40) at Thread.cc:88
#52 0x00007ffff6545b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#53 0x00007ffff558c7bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#54 0x0000000000000000 in ?? ()
{noformat}
Debug output from the plugin
{noformat}
[Mar 19 11:27:29.173] Server {0x2afb87afae00} DIAG: (maybebug) new instance
[Mar 19 11:29:39.786] Server {0x2afb88608700} DIAG: (maybebug) lookup complete: 1
[Mar 19 11:29:39.790] Server {0x2afb88608700} DIAG: (maybebug) read response
[Mar 19 11:29:40.420] Server {0x2afb88507700} DIAG: (maybebug) lookup complete: 2
[Mar 19 11:29:40.420] Server {0x2afb88507700} DIAG: (maybebug) set stale
{noformat}
> Renaming Cache-Control in read-response and marking the cache STALE in lookup-complete causes abort()
> -----------------------------------------------------------------------------------------------------
>
> Key: TS-3455
> URL: https://issues.apache.org/jira/browse/TS-3455
> Project: Traffic Server
> Issue Type: Bug
> Reporter: Luca Bruno
>
> I've written a simple test case plugin for demonstrating this problem, not sure if it's a problem on my side.
> What the plugin does:
> 1) In READ_RESPONSE_HDR rename Cache-Control to X-Plugin-Cache-Control
> 2) In LOOKUP_COMPLETE, if it's a FRESH hit set the status to be STALE instead
> So after the cache has been enabled, do a first request: this will be cached because there's no Cache-Control header.
> Do a second request, now ATS will abort().
> The issue is related to both the fact that Cache-Control is renamed and the cache set to be stale. Either of the two alone don't trigger the issue.
> Plugin code:
> {noformat}
> #include <ts/ts.h>
> #include <ts/remap.h>
> #include <ts/experimental.h>
> #include <stdlib.h>
> #include <stdio.h>
> #include <getopt.h>
> #include <string.h>
> #include <string>
> #include <iterator>
> #include <map>
> // Constants and some declarations
> const char PLUGIN_NAME[] = "maybebug";
> static int Handler(TSCont cont, TSEvent event, void *edata);
> struct PluginState {
> PluginState()
> {
> cont = TSContCreate(Handler, NULL);
> TSContDataSet(cont, this);
> }
> ~PluginState()
> {
> TSContDestroy(cont);
> }
> TSCont cont;
> };
> static int Handler(TSCont cont, TSEvent event, void* edata) {
> TSHttpTxn txn = (TSHttpTxn)edata;
> TSMBuffer mbuf;
> TSMLoc hdrp;
> if (event == TS_EVENT_HTTP_READ_RESPONSE_HDR) {
> TSDebug(PLUGIN_NAME, "read response");
> if (TS_SUCCESS == TSHttpTxnServerRespGet(txn, &mbuf, &hdrp)) {
> TSMLoc fieldp = TSMimeHdrFieldFind(mbuf, hdrp, "Cache-Control", sizeof("Cache-Control")-1);
> if (fieldp != TS_NULL_MLOC) {
> TSDebug(PLUGIN_NAME, "rename cache-control");
> TSMimeHdrFieldNameSet(mbuf, hdrp, fieldp, "X-Plugin-Cache-Control", sizeof("X-Plugin-Cache-Control")-1);
> TSHandleMLocRelease(mbuf, hdrp, fieldp);
> }
> TSHandleMLocRelease(mbuf, TS_NULL_MLOC, hdrp);
> }
> } else if (event == TS_EVENT_HTTP_CACHE_LOOKUP_COMPLETE) {
> int lookup_status;
> if (TS_SUCCESS != TSHttpTxnCacheLookupStatusGet(txn, &lookup_status)) {
> goto beach;
> }
> TSDebug(PLUGIN_NAME, "lookup complete: %d", lookup_status);
> if (lookup_status == TS_CACHE_LOOKUP_HIT_FRESH && TSHttpTxnCachedRespGet(txn, &mbuf, &hdrp) == TS_SUCCESS) {
> TSMLoc fieldp = TSMimeHdrFieldFind(mbuf, hdrp, "X-Plugin-Cache-Control", sizeof("X-Plugin-Cache-Control")-1);
> if (fieldp) {
> TSDebug(PLUGIN_NAME, "set stale");
> TSHandleMLocRelease(mbuf, hdrp, fieldp);
> TSHttpTxnCacheLookupStatusSet(txn, TS_CACHE_LOOKUP_HIT_STALE);
> }
> TSHandleMLocRelease(mbuf, TS_NULL_MLOC, hdrp);
> }
> }
> beach:
> TSHttpTxnReenable(txn, TS_EVENT_HTTP_CONTINUE);
> return TS_EVENT_NONE;
> }
> TSReturnCode TSRemapInit(TSRemapInterface* api, char* errbuf, int bufsz) {
> return TS_SUCCESS;
> }
> TSReturnCode TSRemapNewInstance(int argc, char* argv[], void** instance, char* errbuf, int errbuf_size) {
> TSDebug(PLUGIN_NAME, "new instance");
> PluginState* es = new PluginState();
> *instance = es;
> return TS_SUCCESS;
> }
> void TSRemapDeleteInstance(void* instance) {
> delete static_cast<PluginState*>(instance);
> }
> TSRemapStatus TSRemapDoRemap(void* instance, TSHttpTxn txn, TSRemapRequestInfo* rri) {
> PluginState* es = static_cast<PluginState*>(instance);
> TSHttpTxnHookAdd(txn, TS_HTTP_READ_RESPONSE_HDR_HOOK, es->cont);
> TSHttpTxnHookAdd(txn, TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK, es->cont);
> return TSREMAP_NO_REMAP;
> }
> {noformat}
> Stacktrace from gdb:
> {noformat}
> #1 0x00007ffff54e53e0 in abort () from /lib/x86_64-linux-gnu/libc.so.6
> #2 0x00007ffff7bb96fc in ink_die_die_die (retval=1) at ink_error.cc:43
> #3 0x00007ffff7bb97c2 in ink_fatal_va(int, const char *, typedef __va_list_tag __va_list_tag *) (return_code=1, fmt=0x7ffff7bca490 "%s:%d: failed assert `%s`", ap=0x7ffff42813d8)
> at ink_error.cc:67
> #4 0x00007ffff7bb986d in ink_fatal (return_code=1, message_format=0x7ffff7bca490 "%s:%d: failed assert `%s`") at ink_error.cc:75
> #5 0x00007ffff7bb73a0 in _ink_assert (expression=0x7c6883 "s->pending_work == NULL", file=0x7c66cc "HttpTransact.cc", line=433) at ink_assert.cc:37
> #6 0x000000000060d0aa in how_to_open_connection (s=0x7fffdacac9d0) at HttpTransact.cc:433
> #7 0x0000000000619206 in HttpTransact::HandleCacheOpenReadHit (s=0x7fffdacac9d0) at HttpTransact.cc:2684
> #8 0x00000000005ffd21 in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6954
> #9 0x00000000005ebc20 in HttpSM::handle_api_return (this=0x7fffdacac960) at HttpSM.cc:1532
> #10 0x00000000005eb9d5 in HttpSM::state_api_callout (this=0x7fffdacac960, event=0, data=0x0) at HttpSM.cc:1464
> #11 0x00000000005f8bcb in HttpSM::do_api_callout_internal (this=0x7fffdacac960) at HttpSM.cc:4912
> #12 0x0000000000606999 in HttpSM::do_api_callout (this=0x7fffdacac960) at HttpSM.cc:450
> #13 0x00000000005ffed0 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:6996
> #14 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6962
> #15 0x00000000005f5378 in HttpSM::do_hostdb_lookup (this=0x7fffdacac960) at HttpSM.cc:4043
> #16 0x0000000000600874 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:7092
> #17 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6962
> #18 0x00000000005ebc20 in HttpSM::handle_api_return (this=0x7fffdacac960) at HttpSM.cc:1532
> #19 0x00000000005eb9d5 in HttpSM::state_api_callout (this=0x7fffdacac960, event=60000, data=0x0) at HttpSM.cc:1464
> #20 0x00000000005eb0dc in HttpSM::state_api_callback (this=0x7fffdacac960, event=60000, data=0x0) at HttpSM.cc:1282
> #21 0x0000000000531919 in TSHttpTxnReenable (txnp=0x7fffdacac960, event=TS_EVENT_HTTP_CONTINUE) at InkAPI.cc:5577
> #22 0x00007fffef64a0cc in Handler (cont=0x1315040, event=TS_EVENT_HTTP_CACHE_LOOKUP_COMPLETE, edata=0x7fffdacac960) at bug.cxx:68
> #23 0x0000000000525ebf in INKContInternal::handle_event (this=0x1315040, event=60015, edata=0x7fffdacac960) at InkAPI.cc:1008
> #24 0x00000000005112d4 in Continuation::handleEvent (this=0x1315040, event=60015, data=0x7fffdacac960) at ../iocore/eventsystem/I_Continuation.h:146
> #25 0x00000000005267de in APIHook::invoke (this=0x1399eb0, event=60015, edata=0x7fffdacac960) at InkAPI.cc:1227
> #26 0x00000000005eb764 in HttpSM::state_api_callout (this=0x7fffdacac960, event=0, data=0x0) at HttpSM.cc:1389
> #27 0x00000000005f8bcb in HttpSM::do_api_callout_internal (this=0x7fffdacac960) at HttpSM.cc:4912
> #28 0x0000000000606999 in HttpSM::do_api_callout (this=0x7fffdacac960) at HttpSM.cc:450
> #29 0x00000000005ffed0 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:6996
> #30 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0) at HttpSM.cc:6962
> #31 0x00000000005ebc20 in HttpSM::handle_api_return (this=0x7fffdacac960) at HttpSM.cc:1532
> #32 0x00000000005eb9d5 in HttpSM::state_api_callout (this=0x7fffdacac960, event=0, data=0x0) at HttpSM.cc:1464
> #33 0x00000000005f8bcb in HttpSM::do_api_callout_internal (this=0x7fffdacac960) at HttpSM.cc:4912
> #34 0x0000000000606999 in HttpSM::do_api_callout (this=0x7fffdacac960) at HttpSM.cc:450
> #35 0x00000000005ffed0 in HttpSM::set_next_state (this=0x7fffdacac960) at HttpSM.cc:6996
> #36 0x00000000005ffe6a in HttpSM::call_transact_and_set_next_state (this=0x7fffdacac960, f=0x6162d2 <HttpTransact::HandleCacheOpenRead(HttpTransact::State*)>) at HttpSM.cc:6962
> #37 0x00000000005ef48b in HttpSM::state_cache_open_read (this=0x7fffdacac960, event=1102, data=0x15ad510) at HttpSM.cc:2515
> #38 0x00000000005ef9b8 in HttpSM::main_handler (this=0x7fffdacac960, event=1102, data=0x15ad510) at HttpSM.cc:2574
> #39 0x00000000005112d4 in Continuation::handleEvent (this=0x7fffdacac960, event=1102, data=0x15ad510) at ../iocore/eventsystem/I_Continuation.h:146
> #40 0x00000000005da01c in HttpCacheSM::state_cache_open_read (this=0x7fffdacae398, event=1102, data=0x15ad510) at HttpCacheSM.cc:118
> #41 0x00000000005112d4 in Continuation::handleEvent (this=0x7fffdacae398, event=1102, data=0x15ad510) at ../iocore/eventsystem/I_Continuation.h:146
> #42 0x000000000073686f in CacheVC::callcont (this=0x15ad510, event=1102) at P_CacheInternal.h:661
> #43 0x00000000007349a9 in CacheVC::openReadStartEarliest (this=0x15ad510) at CacheRead.cc:955
> #44 0x00000000005112d4 in Continuation::handleEvent (this=0x15ad510, event=3900, data=0x0) at ../iocore/eventsystem/I_Continuation.h:146
> #45 0x0000000000713740 in CacheVC::handleReadDone (this=0x15ad510, event=3900, e=0x15ad698) at Cache.cc:2668
> #46 0x00000000005112d4 in Continuation::handleEvent (this=0x15ad510, event=3900, data=0x15ad698) at ../iocore/eventsystem/I_Continuation.h:146
> #47 0x0000000000718d11 in AIOCallbackInternal::io_complete (this=0x15ad698, event=1, data=0x1172c70) at ../../iocore/aio/P_AIO.h:124
> #48 0x00000000005112d4 in Continuation::handleEvent (this=0x15ad698, event=1, data=0x1172c70) at ../iocore/eventsystem/I_Continuation.h:146
> #49 0x000000000078ed3d in EThread::process_event (this=0x7ffff4688010, e=0x1172c70, calling_code=1) at UnixEThread.cc:144
> #50 0x000000000078ef91 in EThread::execute (this=0x7ffff4688010) at UnixEThread.cc:195
> #51 0x000000000078e272 in spawn_thread_internal (a=0x1130c40) at Thread.cc:88
> #52 0x00007ffff6545b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
> #53 0x00007ffff558c7bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
> #54 0x0000000000000000 in ?? ()
> {noformat}
> Debug output from the plugin
> {noformat}
> [Mar 19 11:27:29.173] Server {0x2afb87afae00} DIAG: (maybebug) new instance
> [Mar 19 11:29:39.786] Server {0x2afb88608700} DIAG: (maybebug) lookup complete: 1
> [Mar 19 11:29:39.790] Server {0x2afb88608700} DIAG: (maybebug) read response
> [Mar 19 11:29:40.240] Server {0x2afb88608700} DIAG: (maybebug) rename cache-control
> [Mar 19 11:29:40.420] Server {0x2afb88507700} DIAG: (maybebug) lookup complete: 2
> [Mar 19 11:29:40.420] Server {0x2afb88507700} DIAG: (maybebug) set stale
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)