[
https://issues.apache.org/jira/browse/TS-3949?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14909804#comment-14909804
]
Sudheer Vinukonda commented on TS-3949:
---------------------------------------
Another related issue - perhaps, on a read/write, we should also check if the
vio's continuation in PluginVC is dead and not call handle_event (which would
assert).
{code}
(gdb) bt
#0 0x00002b5379e21625 in raise () from /lib64/libc.so.6
#1 0x00002b5379e22e05 in abort () from /lib64/libc.so.6
#2 0x00002b537722a018 in ink_die_die_die (retval=1) at ink_error.cc:43
#3 0x00002b537722a0e5 in ink_fatal_va(int, const char *, typedef __va_list_tag
__va_list_tag *) (return_code=1, message_format=0x2b5377238d78 "%s:%d: failed
assert `%s`", ap=0x2b5381311900)
at ink_error.cc:65
#4 0x00002b537722a1ae in ink_fatal (return_code=1,
message_format=0x2b5377238d78 "%s:%d: failed assert `%s`") at ink_error.cc:73
#5 0x00002b5377228d20 in _ink_assert (expression=0x770ba0 "!\"Plugin tries to
use a continuation which is deleted\"", file=0x770b3d "InkAPI.cc", line=990) at
ink_assert.cc:37
#6 0x000000000050d6bc in INKContInternal::handle_event (this=0x2b538c221400,
event=100, edata=0x2b54d0017e00) at InkAPI.cc:990
#7 0x00000000004f8d4c in Continuation::handleEvent (this=0x2b538c221400,
event=100, data=0x2b54d0017e00) at ../iocore/eventsystem/I_Continuation.h:146
#8 0x0000000000534355 in PluginVC::process_read_side (this=0x2b54d0017d00,
other_side_call=true) at PluginVC.cc:670
#9 0x0000000000533bea in PluginVC::process_write_side (this=0x2b54d0017ee8,
other_side_call=false) at PluginVC.cc:566
#10 0x0000000000532904 in PluginVC::main_handler (this=0x2b54d0017ee8, event=1,
data=0x2b54c405ee80) at PluginVC.cc:212
#11 0x00000000004f8d4c in Continuation::handleEvent (this=0x2b54d0017ee8,
event=1, data=0x2b54c405ee80) at ../iocore/eventsystem/I_Continuation.h:146
#12 0x000000000076080a in EThread::process_event (this=0x2b5380707010,
e=0x2b54c405ee80, calling_code=1) at UnixEThread.cc:145
#13 0x00000000007609d8 in EThread::execute (this=0x2b5380707010) at
UnixEThread.cc:196
#14 0x000000000075fd7c in spawn_thread_internal (a=0x11581c0) at Thread.cc:88
#15 0x00002b5378ee09d1 in start_thread () from /lib64/libpthread.so.0
#16 0x00002b5379ed78fd in clone () from /lib64/libc.so.6
(gdb) f 6
#6 0x000000000050d6bc in INKContInternal::handle_event (this=0x2b538c221400,
event=100, edata=0x2b54d0017e00) at InkAPI.cc:990
990 InkAPI.cc: No such file or directory.
in InkAPI.cc
(gdb) p *this
$1 = {<DummyVConnection> = {<VConnection> = {<Continuation> =
{<force_VFPT_to_top> = {_vptr.force_VFPT_to_top = 0x2b54642db000}, handler =
(int (Continuation::*)(Continuation *, int,
void *)) 0x50d686 <INKContInternal::handle_event(int, void*)>, mutex =
{m_ptr = 0x0}, link = {<SLink<Continuation>> = {next = 0x0}, prev = 0x0}},
lerrno = 0}, <No data fields>},
mdata = 0x2b54d0001280, m_event_func = 0x2b5383b8bebc
<handleHttpFetchIOEvents(TSCont, TSEvent, void*)>, m_event_count = 0, m_closed
= 1, m_deletable = 1, m_deleted = 1,
m_free_magic = INKCONT_INTERN_MAGIC_DEAD}
(gdb) f 8
#8 0x0000000000534355 in PluginVC::process_read_side (this=0x2b54d0017d00,
other_side_call=true) at PluginVC.cc:670
670 PluginVC.cc: No such file or directory.
in PluginVC.cc
(gdb) p closed
$2 = false
(gdb) p read_side
No symbol "read_side" in current context.
(gdb) p read_state
$3 = {vio = {_cont = 0x2b538c221400, nbytes = 9223372036854775807, ndone = 477,
op = 1, buffer = {mbuf = 0x2b548c15f390, entry = 0x0}, vc_server =
0x2b54d0017d00, mutex = {
m_ptr = 0x2b548c0b9840}}, shutdown = false}
(gdb) p write_state
$4 = {vio = {_cont = 0x2b538c221400, nbytes = 125, ndone = 125, op = 2, buffer
= {mbuf = 0x2b546404c910, entry = 0x2b546404c928}, vc_server = 0x2b54d0017d00,
mutex = {m_ptr = 0x2b548c0b9840}},
shutdown = false}
(gdb) p magci
No symbol "magci" in current context.
(gdb) p magic
$5 = 2864434397
(gdb) p/x magic
$6 = 0xaabbccdd
(gdb) f 8
#8 0x0000000000534355 in PluginVC::process_read_side (this=0x2b54d0017d00,
other_side_call=true) at PluginVC.cc:670
670 in PluginVC.cc
(gdb) p read_state
$7 = {vio = {_cont = 0x2b538c221400, nbytes = 9223372036854775807, ndone = 477,
op = 1, buffer = {mbuf = 0x2b548c15f390, entry = 0x0}, vc_server =
0x2b54d0017d00, mutex = {
m_ptr = 0x2b548c0b9840}}, shutdown = false}
(gdb) p *(INKContInternal*) 0x2b538c221400
$8 = {<DummyVConnection> = {<VConnection> = {<Continuation> =
{<force_VFPT_to_top> = {_vptr.force_VFPT_to_top = 0x2b54642db000}, handler =
(int (Continuation::*)(Continuation *, int,
void *)) 0x50d686 <INKContInternal::handle_event(int, void*)>, mutex =
{m_ptr = 0x0}, link = {<SLink<Continuation>> = {next = 0x0}, prev = 0x0}},
lerrno = 0}, <No data fields>},
mdata = 0x2b54d0001280, m_event_func = 0x2b5383b8bebc
<handleHttpFetchIOEvents(TSCont, TSEvent, void*)>, m_event_count = 0, m_closed
= 1, m_deletable = 1, m_deleted = 1,
m_free_magic = INKCONT_INTERN_MAGIC_DEAD}
(gdb) p closed
$9 = false
(gdb)
$10 = false
{code}
> Active timeout event on PluginVC may fire after it's already closed.
> --------------------------------------------------------------------
>
> Key: TS-3949
> URL: https://issues.apache.org/jira/browse/TS-3949
> Project: Traffic Server
> Issue Type: Bug
> Components: Core, Plugins
> Reporter: Sudheer Vinukonda
> Assignee: Sudheer Vinukonda
> Fix For: 6.1.0
>
>
> When a plugin sets TS_EVENT_VCONN_ACTIVE_TIMEOUT on Plugin VC, it looks like,
> in some race conditions, the active timer event could still get fired after
> the Plugin VC is already closed, leading INKContInternal::handle_event to
> assert a use-after-free.
> Note: The plugin VC's process_close does cancel the active timeout event, so,
> this doesn't happen every time. It might happen in some race conditions or
> when the timeout and close are on different threads (?)..
> Below's the fatal log and gdb info of the assert for the timeout event after
> a close.
> {code}
> Sep 26 21:54:54 my_dev_host traffic_server[20653]: FATAL: InkAPI.cc:990:
> failed assert `!"Plugin tries to use a continuation which is deleted"`
> gdb stack trace:
> Core was generated by `/home/y/bin/traffic_server -M --httpport
> 80:fd=8,443:fd=9:ssl'.
> Program terminated with signal 6, Aborted.
> #0 0x00000038fb432625 in raise (sig=6) at
> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
> 64 return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
> (gdb) bt
> #0 0x00000038fb432625 in raise (sig=6) at
> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
> #1 0x00000038fb433e05 in abort () at abort.c:92
> #2 0x00002ad27ce81018 in ink_die_die_die (retval=1) at ink_error.cc:43
> #3 0x00002ad27ce810e5 in ink_fatal_va(int, const char *, typedef
> __va_list_tag __va_list_tag *) (return_code=1, message_format=0x2ad27ce8fd78
> "%s:%d: failed assert `%s`", ap=0x2ad27f7159f0)
> at ink_error.cc:65
> #4 0x00002ad27ce811ae in ink_fatal (return_code=1,
> message_format=0x2ad27ce8fd78 "%s:%d: failed assert `%s`") at ink_error.cc:73
> #5 0x00002ad27ce7fd20 in _ink_assert (expression=0x770ba0 "!\"Plugin tries
> to use a continuation which is deleted\"", file=0x770b3d "InkAPI.cc",
> line=990) at ink_assert.cc:37
> #6 0x000000000050d6bc in INKContInternal::handle_event (this=0x2ad37b27e500,
> event=106, edata=0x2ad3d0000ad0) at InkAPI.cc:990
> #7 0x00000000004f8d4c in Continuation::handleEvent (this=0x2ad37b27e500,
> event=106, data=0x2ad3d0000ad0) at ../iocore/eventsystem/I_Continuation.h:146
> #8 0x000000000053478b in PluginVC::process_timeout (this=0x2ad3d00009d0,
> e=0x2ad360081ef0, event_to_send=106, our_eptr=0x2ad3d0000b88) at
> PluginVC.cc:762
> #9 0x00000000005327b1 in PluginVC::main_handler (this=0x2ad3d00009d0,
> event=2, data=0x2ad360081ef0) at PluginVC.cc:193
> #10 0x00000000004f8d4c in Continuation::handleEvent (this=0x2ad3d00009d0,
> event=2, data=0x2ad360081ef0) at ../iocore/eventsystem/I_Continuation.h:146
> #11 0x000000000076080a in EThread::process_event (this=0x2ad27eb0b010,
> e=0x2ad360081ef0, calling_code=2) at UnixEThread.cc:145
> #12 0x0000000000760b25 in EThread::execute (this=0x2ad27eb0b010) at
> UnixEThread.cc:224
> #13 0x000000000075fd7c in spawn_thread_internal (a=0x2fc9f80) at Thread.cc:88
> #14 0x00002ad27d4009d1 in start_thread (arg=0x2ad27f716700) at
> pthread_create.c:301
> #15 0x00000038fb4e88fd in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
> (gdb) bt
> #0 0x00000038fb432625 in raise (sig=6) at
> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
> #1 0x00000038fb433e05 in abort () at abort.c:92
> #2 0x00002ad27ce81018 in ink_die_die_die (retval=1) at ink_error.cc:43
> #3 0x00002ad27ce810e5 in ink_fatal_va(int, const char *, typedef
> __va_list_tag __va_list_tag *) (return_code=1, message_format=0x2ad27ce8fd78
> "%s:%d: failed assert `%s`", ap=0x2ad27f7159f0)
> at ink_error.cc:65
> #4 0x00002ad27ce811ae in ink_fatal (return_code=1,
> message_format=0x2ad27ce8fd78 "%s:%d: failed assert `%s`") at ink_error.cc:73
> #5 0x00002ad27ce7fd20 in _ink_assert (expression=0x770ba0 "!\"Plugin tries
> to use a continuation which is deleted\"", file=0x770b3d "InkAPI.cc",
> line=990) at ink_assert.cc:37
> #6 0x000000000050d6bc in INKContInternal::handle_event (this=0x2ad37b27e500,
> event=106, edata=0x2ad3d0000ad0) at InkAPI.cc:990
> #7 0x00000000004f8d4c in Continuation::handleEvent (this=0x2ad37b27e500,
> event=106, data=0x2ad3d0000ad0) at ../iocore/eventsystem/I_Continuation.h:146
> #8 0x000000000053478b in PluginVC::process_timeout (this=0x2ad3d00009d0,
> e=0x2ad360081ef0, event_to_send=106, our_eptr=0x2ad3d0000b88) at
> PluginVC.cc:762
> #9 0x00000000005327b1 in PluginVC::main_handler (this=0x2ad3d00009d0,
> event=2, data=0x2ad360081ef0) at PluginVC.cc:193
> #10 0x00000000004f8d4c in Continuation::handleEvent (this=0x2ad3d00009d0,
> event=2, data=0x2ad360081ef0) at ../iocore/eventsystem/I_Continuation.h:146
> #11 0x000000000076080a in EThread::process_event (this=0x2ad27eb0b010,
> e=0x2ad360081ef0, calling_code=2) at UnixEThread.cc:145
> #12 0x0000000000760b25 in EThread::execute (this=0x2ad27eb0b010) at
> UnixEThread.cc:224
> #13 0x000000000075fd7c in spawn_thread_internal (a=0x2fc9f80) at Thread.cc:88
> #14 0x00002ad27d4009d1 in start_thread (arg=0x2ad27f716700) at
> pthread_create.c:301
> #15 0x00000038fb4e88fd in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
> (gdb) f
> #6 0x000000000050d6bc in INKContInternal::handle_event (this=0x2ad37b27e500,
> event=106, edata=0x2ad3d0000ad0) at InkAPI.cc:990
> 990 in InkAPI.cc
> (gdb) p *this
> $5 = {<DummyVConnection> = {<VConnection> = {<Continuation> =
> {<force_VFPT_to_top> = {_vptr.force_VFPT_to_top = 0x2ad36b9a1190}, handler =
> (int (Continuation::*)(Continuation *, int,
> void *)) 0x50d686 <INKContInternal::handle_event(int, void*)>, mutex =
> {m_ptr = 0x0}, link = {<SLink<Continuation>> = {next = 0x0}, prev = 0x0}},
> lerrno = 0}, <No data fields>},
> mdata = 0x2ad72815ed20, m_event_func = 0x2ad356aa9843
> <send_response_handler(TSCont, TSEvent, void*)>, m_event_count = 0, m_closed
> = 1, m_deletable = 1, m_deleted = 1,
> m_free_magic = INKCONT_INTERN_MAGIC_DEAD}
> (gdb)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
