[
https://issues.apache.org/jira/browse/TS-4916?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15565557#comment-15565557
]
Gancho Tenev edited comment on TS-4916 at 10/11/16 3:02 PM:
------------------------------------------------------------
[~shinrich], appreciate your comment!
I am running with version 6.2.1 and not with master.
{{DLL<>}} not being thread-safe and multiple threads manipulating it
concurrently was the first thing that came to mind. Changed the code so
{{client_streams_count}} ++ / -- and {{stream_list.push()}} /
{{stream_list.remove()}} are called from only 2 corresponding new functions
{{add_to_active_streams()}} and {{rm_from_active_streams()}} (in
{{Http2ConnectionState}}) and added assert like the following:
{code}
(1) ink_assert(this->mutex->thread_holding == this_ethread());
{code}
which never triggered in my case (9+ days already)!
In fact traffic_server gets into the same broken state described in my previous
post (broken DLL structure with few elements where the last element points to
itself) reliably and consistently on all the machines I inspected (10+ at this
time) and I saw the same symptoms (cache update failures skyrocket after the
H2-infinite loop happens) on many more machines.
Then came up with the hypothesis described earlier and added the following
assert to the {{add_to_active_streams()}} function:
{code}
(2) ink_assert(stream_list.in(stream));
{code}
which started triggering quickly (for < 1 day) on all machines I tested. It was
always the case that {{stream_list.head == new_stream}} (memory chunk with the
same address have been already added to stream_list).
Then changed the {{Http2Stream::delete_stream()}} to be called safely even if
already deleted and added a “catch-all” call in {{Http2Stream::destroy()}} to
make sure stream is deleted before destroying and the problem never happened
((1) and (2) never triggered for at least 3+ days).
Looking into it more it turned out if {{Http2Stream::do_io_close()}} gets into
{{_state==HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE}} (in version 6.2.1) it misses
to delete the stream before it orders the stream self destruction (few lines
below) so when it gets to {{Http2Stream::destroy()}} it frees the memory
without removing the stream from the active list and then it runs into the
H2-infinite-loop if the sequence of events described in my previous post
happens.
Making sure {{Http2Stream::do_io_close()}} deletes the stream before requesting
the self-destruction (with {{VC_EVENT_EOS}}) fixes the problem (it can be
solved in many different ways).
Although I can see that there might be a race condition in that part of the
code I just have never run into it ((1) never triggers and all experiments fit
pretty well what I described in my previous post)
After your comment I identified 4 places where we might not be holding the lock
properly when modifying stream_list/client_stream_cout (not actually happening,
just reading/tracing the code), added them and repeated the experiments and got
the same results (including the failures (2) and the fix).
I see that the master code has changed quite a lot since 6.2.1, checked with
[~zwoop] and will probably prepare a PR for a back port to 6.2.x.
Since the master code changed (i.e. {{Http2Stream::do_io_close()}}) there is a
chance we don’t run into this H2-infinite-loop condition anymore (have not
tested it yet) but we still use {{DLL<>}} and a memory pool in the same way so
it seems possible that we can run into the same problem if we are not careful
and will study the new master code more to see if we can do something to avoid
it.
Cheers,
—Gancho
was (Author: gancho):
[~shinrich], appreciate your comment!
I am running with version 6.2.1 and not with master.
{{DLL<>}} not being thread-safe and multiple threads manipulating it
concurrently was the first thing that came to mind. Changed the code so
{{client_streams_count}} ++ / -- and {{stream_list.push()}} /
{{stream_list.remove()}} are called from only 2 corresponding new functions
{{add_to_active_streams()}} and {{rm_from_active_streams()}} (in
{{Http2ConnectionState}}) and added assert like the following:
{code}
(1) ink_assert(this->mutex->thread_holding == this_ethread());
{code}
which never triggered in my case (9+ days already)!
In fact traffic_server gets into the same broken state described in my previous
post (broken DLL structure with few elements where the last element points to
itself) reliably and consistently on all the machines I inspected (10+ at this
time) and I saw the same symptoms (cache update failures skyrocket after the
H2-infinite loop happens) on many more machines.
Then came up with the hypothesis described earlier and added the following
assert to the {{add_to_active_streams()}} function:
{code}
(2) ink_assert(stream_list.in(stream));
{code}
which started triggering quickly (for < 1 day) on all machines I tested. It was
always the case that {{stream_list.head == new_stream}} (memory chunk with the
same address have been already added to stream_list).
Then changed the {{Http2Stream::delete_stream()}} to be called safely even if
already deleted and added a “catch-all” call in {{Http2Stream::destroy()}} to
make sure stream is deleted before destroying and the problem never happened
((1) and (2) never triggered for at least 3+ days).
Looking into it more it turned out if {{Http2Stream::do_io_close()}} gets into
{{_state==HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE}} (in version 6.2.1) it misses
to delete the stream before it orders the stream self destruction (few lines
below) so when it gets to {{Http2Stream::destroy()}} it frees the memory
without removing the stream from the active list and then it runs into the
H2-infinite-loop if the sequence of events described in my previous post
happens.
Making sure {{Http2Stream::destroy()}} deletes the stream before requesting the
self-destruction (with {{VC_EVENT_EOS}}) fixes the problem (it can be solved in
many different ways).
Although I can see that there might be a race condition in that part of the
code I just have never run into it ((1) never triggers and all experiments fit
pretty well what I described in my previous post)
After your comment I identified 4 places where we might not be holding the lock
properly when modifying stream_list/client_stream_cout (not actually happening,
just reading/tracing the code), added them and repeated the experiments and got
the same results (including the failures (2) and the fix).
I see that the master code has changed quite a lot since 6.2.1, checked with
[~zwoop] and will probably prepare a PR for a back port to 6.2.x.
Since the master code changed (i.e. {{Http2Stream::do_io_close()}}) there is a
chance we don’t run into this H2-infinite-loop condition anymore (have not
tested it yet) but we still use {{DLL<>}} and a memory pool in the same way so
it seems possible that we can run into the same problem if we are not careful
and will study the new master code more to see if we can do something to avoid
it.
Cheers,
—Gancho
> Http2ConnectionState::restart_streams infinite loop causes deadlock
> --------------------------------------------------------------------
>
> Key: TS-4916
> URL: https://issues.apache.org/jira/browse/TS-4916
> Project: Traffic Server
> Issue Type: Bug
> Components: Core, HTTP/2
> Reporter: Gancho Tenev
> Assignee: Gancho Tenev
> Priority: Blocker
> Fix For: 7.1.0
>
>
> Http2ConnectionState::restart_streams falls into an infinite loop while
> holding a lock, which leads to cache updates to start failing.
> The infinite loop is caused by traversing a list whose last element “next”
> points to the element itself and the traversal never finishes.
> {code}
> Thread 51 (Thread 0x2aaab3d04700 (LWP 34270)):
> #0 0x00002aaaaacf3fee in Http2ConnectionState::restart_streams
> (this=0x2ae6ba5284c8) at Http2ConnectionState.cc:913
> #1 rcv_window_update_frame (cstate=..., frame=...) at
> Http2ConnectionState.cc:627
> #2 0x00002aaaaacf9738 in Http2ConnectionState::main_event_handler
> (this=0x2ae6ba5284c8, event=<optimized out>, edata=<optimized out>) at
> Http2ConnectionState.cc:823
> #3 0x00002aaaaacef1c3 in Continuation::handleEvent (data=0x2aaab3d039a0,
> event=2253, this=0x2ae6ba5284c8) at
> ../../iocore/eventsystem/I_Continuation.h:153
> #4 send_connection_event (cont=cont@entry=0x2ae6ba5284c8,
> event=event@entry=2253, edata=edata@entry=0x2aaab3d039a0) at
> Http2ClientSession.cc:58
> #5 0x00002aaaaacef462 in Http2ClientSession::state_complete_frame_read
> (this=0x2ae6ba528290, event=<optimized out>, edata=0x2aab7b237f18) at
> Http2ClientSession.cc:426
> #6 0x00002aaaaacf0982 in Continuation::handleEvent (data=0x2aab7b237f18,
> event=100, this=0x2ae6ba528290) at
> ../../iocore/eventsystem/I_Continuation.h:153
> #7 Http2ClientSession::state_start_frame_read (this=0x2ae6ba528290,
> event=<optimized out>, edata=0x2aab7b237f18) at Http2ClientSession.cc:399
> #8 0x00002aaaaacef5a3 in Continuation::handleEvent (data=0x2aab7b237f18,
> event=100, this=0x2ae6ba528290) at
> ../../iocore/eventsystem/I_Continuation.h:153
> #9 Http2ClientSession::state_complete_frame_read (this=0x2ae6ba528290,
> event=<optimized out>, edata=0x2aab7b237f18) at Http2ClientSession.cc:431
> #10 0x00002aaaaacf0982 in Continuation::handleEvent (data=0x2aab7b237f18,
> event=100, this=0x2ae6ba528290) at
> ../../iocore/eventsystem/I_Continuation.h:153
> #11 Http2ClientSession::state_start_frame_read (this=0x2ae6ba528290,
> event=<optimized out>, edata=0x2aab7b237f18) at Http2ClientSession.cc:399
> #12 0x00002aaaaae67e2b in Continuation::handleEvent (data=0x2aab7b237f18,
> event=100, this=<optimized out>) at
> ../../iocore/eventsystem/I_Continuation.h:153
> #13 read_signal_and_update (vc=0x2aab7b237e00, vc@entry=0x1,
> event=event@entry=100) at UnixNetVConnection.cc:153
> #14 UnixNetVConnection::readSignalAndUpdate (this=this@entry=0x2aab7b237e00,
> event=event@entry=100) at UnixNetVConnection.cc:1036
> #15 0x00002aaaaae47653 in SSLNetVConnection::net_read_io
> (this=0x2aab7b237e00, nh=0x2aaab2409cc0, lthread=0x2aaab2406000) at
> SSLNetVConnection.cc:595
> #16 0x00002aaaaae5558c in NetHandler::mainNetEvent (this=0x2aaab2409cc0,
> event=<optimized out>, e=<optimized out>) at UnixNet.cc:513
> #17 0x00002aaaaae8d2e6 in Continuation::handleEvent (data=0x2aaab0bfa700,
> event=5, this=<optimized out>) at I_Continuation.h:153
> #18 EThread::process_event (calling_code=5, e=0x2aaab0bfa700,
> this=0x2aaab2406000) at UnixEThread.cc:148
> #19 EThread::execute (this=0x2aaab2406000) at UnixEThread.cc:275
> #20 0x00002aaaaae8c0e6 in spawn_thread_internal (a=0x2aaab0b25bb0) at
> Thread.cc:86
> #21 0x00002aaaad6b3aa1 in start_thread (arg=0x2aaab3d04700) at
> pthread_create.c:301
> #22 0x00002aaaae8bc93d in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
> {code}
> Here is the stream_list trace.
> {code}
> (gdb) thread 51
> [Switching to thread 51 (Thread 0x2aaab3d04700 (LWP 34270))]
> #0 0x00002aaaaacf3fee in Http2ConnectionState::restart_streams
> (this=0x2ae6ba5284c8) at Http2ConnectionState.cc:913
> (gdb) trace_list stream_list
> ------- count=0 -------
> id=29
> this=0x2ae673f0c840
> next=0x2aaac05d8900
> prev=(nil)
> ------- count=1 -------
> id=27
> this=0x2aaac05d8900
> next=0x2ae5b6bbec00
> prev=0x2ae673f0c840
> ------- count=2 -------
> id=19
> this=0x2ae5b6bbec00
> next=0x2ae5b6bbec00
> prev=0x2aaac05d8900
> ------- count=3 -------
> id=19
> this=0x2ae5b6bbec00
> next=0x2ae5b6bbec00
> prev=0x2aaac05d8900
> . . .
> ------- count=5560 -------
> id=19
> this=0x2ae5b6bbec00
> next=0x2ae5b6bbec00
> prev=0x2aaac05d8900
> . . .
> {code}
> Currently I am working on finding out why the list in question got into this
> “impossible” (broken) state and and eventually coming up with a fix.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
