apache / apache/trafficserver

Failed assertion in http tunnel

Open
#12,244 8 comments 3 reactions 0 assignees View on GitHub
Bug Cache Crash HTTP HttpSM Stale Support
Dominant language
C++
Stars
2k
Forks
874
Avg merge
6d 15h
Merged PRs (30d)
46

Description

This is on version 9.2.10

```
Fatal: HttpTunnel.cc:991: failed assertion `c->skip_bytes <= c->buffer_reader->read_avail()`
```

backtrace

```
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 0x0000152a601e127e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 0x0000152a601c48ff in __GI_abort () at ./stdlib/abort.c:79
#5 0x0000152a60e71e1e in ink_abort (message_format=message_format@entry=0x152a60ee7cdb "%s:%d: failed assertion `%s`") at ink_error.cc:99
#6 0x0000152a60e6e04b in _ink_assert (expression=, file=, line=) at ink_assert.cc:37
#7 0x0000560eb7a58d08 in HttpTunnel::producer_run (this=0x560fcfe5db08, p=0x560fcfe5dd10) at HttpTunnel.cc:991
#8 0x0000560eb7a59b40 in HttpTunnel::tunnel_run (this=0x560fcfe5db08, p_arg=0x560fcfe5dd10) at HttpTunnel.cc:818
#9 0x0000560eb79e439e in HttpSM::state_api_callout (this=this@entry=0x560fcfe5cb00, event=event@entry=60000, data=data@entry=0x0) at HttpSM.cc:1648
#10 0x0000560eb79eb989 in HttpSM::state_api_callback (this=this@entry=0x560fcfe5cb00, event=event@entry=60000, data=data@entry=0x0) at HttpSM.cc:1453
#11 0x0000560eb7962dee in TSHttpTxnReenable (txnp=0x560fcfe5cb00, event=TS_EVENT_HTTP_CONTINUE) at traffic_server/InkAPI.cc:6316
#12 0x0000152a540b625d in transform_plugin (contp=0x1528a21f87a0, event=TS_EVENT_HTTP_READ_RESPONSE_HDR, edata=0x560fcfe5cb00) at compress/compress.cc:908
#13 0x0000560eb7946148 in INKContInternal::handle_event (this=0x1528a21f87a0, event=60006, edata=0x560fcfe5cb00) at traffic_server/InkAPI.cc:1135
#14 0x0000560eb795dc6f in Continuation::handleEvent (data=0x560fcfe5cb00, event=60006, this=0x1528a21f87a0) at /trafficserver/iocore/eventsystem/I_Continuation.h:227
#15 Continuation::handleEvent (data=0x560fcfe5cb00, event=60006, this=0x1528a21f87a0) at /trafficserver/iocore/eventsystem/I_Continuation.h:223
#16 APIHook::invoke (this=this@entry=0x152a3839e1c0, event=60006, edata=edata@entry=0x560fcfe5cb00) at traffic_server/InkAPI.cc:1372
#17 0x0000560eb79e3d41 in HttpSM::state_api_callout (this=this@entry=0x560fcfe5cb00, event=event@entry=60000, data=data@entry=0x0) at HttpSM.cc:1576
#18 0x0000560eb79eb989 in HttpSM::state_api_callback (this=this@entry=0x560fcfe5cb00, event=event@entry=60000, data=data@entry=0x0) at HttpSM.cc:1453
#19 0x0000560eb7962dee in TSHttpTxnReenable (txnp=0x560fcfe5cb00, event=TS_EVENT_HTTP_CONTINUE) at traffic_server/InkAPI.cc:6316
#20 0x0000152a54247ef0 in (anonymous namespace)::invokePluginForEvent (event=TS_EVENT_HTTP_READ_RESPONSE_HDR, ats_txn_handle=0x560fcfe5cb00, plugin=0x152791318a10) at utils_internal.cc:160
#21 atscppapi::utils::internal::invokePluginForEvent (plugin=0x152791318a10, ats_txn_handle=0x560fcfe5cb00, event=TS_EVENT_HTTP_READ_RESPONSE_HDR) at utils_internal.cc:251
#22 0x0000152a54244cc9 in (anonymous namespace)::handleTransactionPluginEvents (cont=0x1529f98f0c40, event=TS_EVENT_HTTP_READ_RESPONSE_HDR, edata=0x560fcfe5cb00) at TransactionPlugin.cc:53
#23 0x0000560eb7946148 in INKContInternal::handle_event (this=0x1529f98f0c40, event=60006, edata=0x560fcfe5cb00) at traffic_server/InkAPI.cc:1135
#24 0x0000560eb795dc6f in Continuation::handleEvent (data=0x560fcfe5cb00, event=60006, this=0x1529f98f0c40) at /trafficserver/iocore/eventsystem/I_Continuation.h:227
#25 Continuation::handleEvent (data=0x560fcfe5cb00, event=60006, this=0x1529f98f0c40) at /trafficserver/iocore/eventsystem/I_Continuation.h:223
#26 APIHook::invoke (this=this@entry=0x152a407a84c0, event=60006, edata=edata@entry=0x560fcfe5cb00) at traffic_server/InkAPI.cc:1372
#27 0x0000560eb79e3d41 in HttpSM::state_api_callout (this=this@entry=0x560fcfe5cb00, event=event@entry=60000, data=data@entry=0x0) at HttpSM.cc:1576
#28 0x0000560eb79eb989 in HttpSM::state_api_callback (this=this@entry=0x560fcfe5cb00, event=event@entry=60000, data=data@entry=0x0) at HttpSM.cc:1453
#29 0x0000560eb7962dee in TSHttpTxnReenable (txnp=0x560fcfe5cb00, event=TS_EVENT_HTTP_CONTINUE) at traffic_server/InkAPI.cc:6316
#30 0x0000152a54248163 in (anonymous namespace)::handleTransactionEvents (cont=, event=, edata=0x560fcfe5cb00) at utils_internal.cc:111
#31 0x0000560eb7946148 in INKContInternal::handle_event (this=0x560eb9b38b00, event=60006, edata=0x560fcfe5cb00) at traffic_server/InkAPI.cc:1135
#32 0x0000560eb795dc6f in Continuation::handleEvent (data=0x560fcfe5cb00, event=60006, this=0x560eb9b38b00) at /trafficserver/iocore/eventsystem/I_Continuation.h:227
#33 Continuation::handleEvent (data=0x560fcfe5cb00, event=60006, this=0x560eb9b38b00) at /trafficserver/iocore/eventsystem/I_Continuation.h:223
#34 APIHook::invoke (this=this@entry=0x560eb9b3af40, event=60006, edata=edata@entry=0x560fcfe5cb00) at traffic_server/InkAPI.cc:1372
#35 0x0000560eb79e3d41 in HttpSM::state_api_callout (this=0x560fcfe5cb00, event=, data=) at HttpSM.cc:1576
#36 0x0000560eb79e5581 in HttpSM::state_read_server_response_header (this=0x560fcfe5cb00, event=, data=) at HttpSM.cc:2154
#37 0x0000560eb79eb6c0 in HttpSM::main_handler (this=0x560fcfe5cb00, event=100, data=0x15299407ec30) at HttpSM.cc:2764
#38 0x0000560eb7cc18bc in Continuation::handleEvent (data=0x15299407ec30, event=100, this=0x560fcfe5cb00) at /trafficserver/iocore/eventsystem/I_Continuation.h:227
#39 Continuation::handleEvent (data=0x15299407ec30, event=100, this=0x560fcfe5cb00) at /trafficserver/iocore/eventsystem/I_Continuation.h:223
#40 read_signal_and_update (event=100, vc=0x15299407ea40) at UnixNetVConnection.cc:83
#41 0x0000560eb7ccaed0 in read_from_net (nh=, vc=0x15299407ea40, thread=) at UnixNetVConnection.cc:323
#42 0x0000560eb7cb013c in NetHandler::process_ready_list (this=this@entry=0x152a5d1e8410) at UnixNet.cc:428
#43 0x0000560eb7cb056b in NetHandler::waitForActivity (this=0x152a5d1e8410, timeout=) at UnixNet.cc:565
#44 0x0000560eb7d12d79 in EThread::execute_regular (this=this@entry=0x152a5d1e4010) at UnixEThread.cc:292
#45 0x0000560eb7d12f51 in EThread::execute (this=0x152a5d1e4010) at UnixEThread.cc:353
#46 EThread::execute (this=0x152a5d1e4010) at UnixEThread.cc:331
#47 0x0000560eb7d109da in spawn_thread_internal (a=0x560eb9ad4ad0) at Thread.cc:78
#48 0x0000152a60238aa4 in start_thread (arg=) at ./nptl/pthread_create.c:447
#49 0x0000152a602c5c3c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78
```

Some notes from poking at the core dump

```
#9 0x0000560eb79e439e in HttpSM::state_api_callout (this=this@entry=0x560fcfe5cb00, event=event@entry=60000, data=data@entry=0x0) at HttpSM.cc:1648

(gdb) p t_state.hdr_info.response_content_length
$2 = 65

(gdb) p t_state.ranges[0]
$3 = {_start = 0, _end = 64, _done_byte = -1}

(gdb) p t_state.hdr_info.server_response.m_http.u.resp.m_status
$10 = 308

(gdb) p t_state.cache_info.action
$15 = HttpTransact::CACHE_DO_WRITE

(gdb) p t_state.cache_info.write_status
$16 = HttpTransact::CACHE_WRITE_IN_PROGRESS

(gdb) p t_state.cache_info.write_lock_state
$17 = HttpTransact::CACHE_WL_SUCCESS
```

```
#7 0x0000560eb7a58d08 in HttpTunnel::producer_run (this=0x560fcfe5db08, p=0x560fcfe5dd10) at HttpTunnel.cc:991

(gdb) p c->skip_bytes
$1 = 316

(gdb) p c->name
$11 = 0x560eb7d56b3b "cache write"
```
I've looked at a few of these crashes, and they were all range requests like above, with the range matching the content length of the server response. The server response code is always a 308.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.