[ 
https://issues.apache.org/jira/browse/TS-3949?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Sudheer Vinukonda updated TS-3949:
----------------------------------
    Description: 
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}

  was:
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 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}


> 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)

Reply via email to