You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by re...@apache.org on 2019/05/05 08:37:19 UTC
[tomcat] branch master updated: Make sure timeout elapses before
calling a timeout
This is an automated email from the ASF dual-hosted git repository.
remm pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/tomcat.git
The following commit(s) were added to refs/heads/master by this push:
new 6232d82 Make sure timeout elapses before calling a timeout
6232d82 is described below
commit 6232d82cc5db73e5da5392d6ec6d9d01ce65c85e
Author: remm <re...@apache.org>
AuthorDate: Sun May 5 10:37:05 2019 +0200
Make sure timeout elapses before calling a timeout
It seems there are extra stream notify as although 0 bytes have been
allocated only a few ms have passed when there is a failure.
---
java/org/apache/coyote/http2/Http2UpgradeHandler.java | 6 ++++--
1 file changed, 4 insertions(+), 2 deletions(-)
diff --git a/java/org/apache/coyote/http2/Http2UpgradeHandler.java b/java/org/apache/coyote/http2/Http2UpgradeHandler.java
index 65c9fe6..97644c4 100644
--- a/java/org/apache/coyote/http2/Http2UpgradeHandler.java
+++ b/java/org/apache/coyote/http2/Http2UpgradeHandler.java
@@ -752,6 +752,7 @@ class Http2UpgradeHandler extends AbstractStream implements InternalHttpUpgradeH
// this thread until after this thread enters wait()
int allocation = 0;
synchronized (stream) {
+ long writeTimeout = protocol.getWriteTimeout();
do {
synchronized (this) {
if (!stream.canWrite()) {
@@ -804,17 +805,18 @@ class Http2UpgradeHandler extends AbstractStream implements InternalHttpUpgradeH
// Connection level window is empty. Although this
// request is for a stream, use the connection
// timeout
- long writeTimeout = protocol.getWriteTimeout();
if (writeTimeout < 0) {
stream.wait();
} else {
+ long t1 = System.currentTimeMillis();
stream.wait(writeTimeout);
+ writeTimeout -= (System.currentTimeMillis() - t1);
}
// Has this stream been granted an allocation
// Note: If the stream in not in this Map then the
// requested write has been fully allocated
int[] value = backLogStreams.get(stream);
- if (value != null && value[1] == 0) {
+ if (writeTimeout <= 0 && value != null && value[1] == 0) {
if (log.isDebugEnabled()) {
log.debug(sm.getString("upgradeHandler.noAllocation",
connectionId));
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: [tomcat] branch master updated: Make sure timeout elapses before
calling a timeout
Posted by Mark Thomas <ma...@apache.org>.
On 10/05/2019 20:02, Rémy Maucherat wrote:
> On Fri, May 10, 2019 at 8:01 PM Mark Thomas <ma...@apache.org> wrote:
>
>> I've just pushed a fix. The tests seem more stable now locally but I am
>> going to keep running them. Thanks for the pointer. The issue was
>> obvious as soon as I read your email.
>>
>> Given the issue has been there for a while, unless anyone objects I am
>> going to go ahead with the releases.
>>
>
> Excellent. Gitbox seems out of sync again [I hope nobody starts using it,
> or we'll end up running into trouble ...],
Gitbox is currently down so at least nothing can get out of sync.
> so no CI run for now, but I'm
> certain it's the right fix [it works for me locally and I could "reliably"
> reproduce the issue with "test-only" and enough runs of the 5_3 test]. My
> original hack doesn't look so bad retrospectively since it is equivalent to
> waiting for the right notify, but it's a good thing to drop weird hacks.
I still see some failures but they are genuine timeouts due to what
looks like GC pauses. I've disabled debug logging again. That might help.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: [tomcat] branch master updated: Make sure timeout elapses before
calling a timeout
Posted by Rémy Maucherat <re...@apache.org>.
On Fri, May 10, 2019 at 8:01 PM Mark Thomas <ma...@apache.org> wrote:
> I've just pushed a fix. The tests seem more stable now locally but I am
> going to keep running them. Thanks for the pointer. The issue was
> obvious as soon as I read your email.
>
> Given the issue has been there for a while, unless anyone objects I am
> going to go ahead with the releases.
>
Excellent. Gitbox seems out of sync again [I hope nobody starts using it,
or we'll end up running into trouble ...], so no CI run for now, but I'm
certain it's the right fix [it works for me locally and I could "reliably"
reproduce the issue with "test-only" and enough runs of the 5_3 test]. My
original hack doesn't look so bad retrospectively since it is equivalent to
waiting for the right notify, but it's a good thing to drop weird hacks.
Rémy
Re: [tomcat] branch master updated: Make sure timeout elapses before
calling a timeout
Posted by Mark Thomas <ma...@apache.org>.
On 10/05/2019 16:50, Rémy Maucherat wrote:
> On Fri, May 10, 2019 at 5:41 PM Mark Thomas <ma...@apache.org> wrote:
>
>> On 10/05/2019 16:26, Rémy Maucherat wrote:
>>> On Fri, May 10, 2019 at 11:14 AM Mark Thomas <ma...@apache.org> wrote:
>>>
>>>> On 09/05/2019 21:53, Mark Thomas wrote:
>>>>> On 05/05/2019 09:37, remm@apache.org wrote:
>>>>>> This is an automated email from the ASF dual-hosted git repository.
>>>>>>
>>>>>> remm pushed a commit to branch master
>>>>>> in repository https://gitbox.apache.org/repos/asf/tomcat.git
>>>>>>
>>>>>>
>>>>>> The following commit(s) were added to refs/heads/master by this push:
>>>>>> new 6232d82 Make sure timeout elapses before calling a timeout
>>>>>> 6232d82 is described below
>>>>>>
>>>>>> commit 6232d82cc5db73e5da5392d6ec6d9d01ce65c85e
>>>>>> Author: remm <re...@apache.org>
>>>>>> AuthorDate: Sun May 5 10:37:05 2019 +0200
>>>>>>
>>>>>> Make sure timeout elapses before calling a timeout
>>>>>>
>>>>>> It seems there are extra stream notify as although 0 bytes have
>> been
>>>>>> allocated only a few ms have passed when there is a failure.
>>>>>
>>>>> I think something else is going on here. I'm still trying to figure it
>>>> out.
>>>>
>>>> I can't reproduce the test failure - either with the code or some code
>>>> written to explicitly test this scenario. However, I do believe I know
>>>> what the problem is.
>>>>
>>>> backLogStreams is a concurrent Map of Stream to int[]. The int[] is a
>>>> two element array where the first element is number of bytes the stream
>>>> requires and the second is the number allocated.
>>>>
>>>> I believe the issue occurs as follows:
>>>> - Thread A requests more bytes for Stream A than are available in the
>>>> connection window
>>>> - Stream A is placed into the backlog
>>>> - Thread A enters streamA.wait()
>>>> - Thread B processes a Window update message
>>>> - Thread B allocates some bytes to streamA
>>>> - Thread B calls streamA.notify()
>>>> - Thread A exits the wait but, because the elements of the int[] are not
>>>> volatile, it does not see the window update
>>>> - Thread A treats existing the wait without an allocation as a timeout
>>>>
>>>> I've left out the obtaining and releasing of locks on streamA and the
>>>> Http2UpgradeHandler for clarity but I'll note that some reads of the
>>>> allocation occur outside of any lock
>>>>
>>>> The above description is consistent with a known failure trace:
>>>>
>>>>
>> https://ci.apache.org/projects/tomcat/tomcat9/logs/4288/TEST-org.apache.coyote.http2.TestHttp2Section_5_3.NIO2.txt
>>>>
>>>> My plan is as follows:
>>>> - revert the "check it has really timed out fix"
>>>> - modify the access to the allocation so that updates to the allocation
>>>> are guaranteed to be visible after the wait() exits
>>>>
>>>
>>> I agree there's something wrong, but the current algorithm may not be
>>> robust enough because anything notifying the stream object will break it.
>>
>> I think we have / had multiple bugs here. That hasn't been helping.
>>
>>> From the logs, the problem (looking only at test 5_3) is with stream 19.
>>> When the test passes, the stream was never actually backloged. When it
>>> fails, it was and the window update frame read does not cause the backlog
>>> release (so when Stream.incrementWindowSize does notifyAll, it breaks).
>>
>> I see what you mean. Waiting on the stream object for the stream window
>> update and the connection window update isn't going to work.
>>
>> If you can see a solution - do let me know. My instinct is that this is
>> going to be a tricky one to fix.
>>
>> Is this a regression that needs to be fixed? Or should I go ahead with
>> the releases. Personally, I'm leaning towards going ahead.
>>
>
> I'm not sure. I don't think it happens without async [for whatever timing
> reason].
I've just pushed a fix. The tests seem more stable now locally but I am
going to keep running them. Thanks for the pointer. The issue was
obvious as soon as I read your email.
Given the issue has been there for a while, unless anyone objects I am
going to go ahead with the releases.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: [tomcat] branch master updated: Make sure timeout elapses before
calling a timeout
Posted by Rémy Maucherat <re...@apache.org>.
On Fri, May 10, 2019 at 5:41 PM Mark Thomas <ma...@apache.org> wrote:
> On 10/05/2019 16:26, Rémy Maucherat wrote:
> > On Fri, May 10, 2019 at 11:14 AM Mark Thomas <ma...@apache.org> wrote:
> >
> >> On 09/05/2019 21:53, Mark Thomas wrote:
> >>> On 05/05/2019 09:37, remm@apache.org wrote:
> >>>> This is an automated email from the ASF dual-hosted git repository.
> >>>>
> >>>> remm pushed a commit to branch master
> >>>> in repository https://gitbox.apache.org/repos/asf/tomcat.git
> >>>>
> >>>>
> >>>> The following commit(s) were added to refs/heads/master by this push:
> >>>> new 6232d82 Make sure timeout elapses before calling a timeout
> >>>> 6232d82 is described below
> >>>>
> >>>> commit 6232d82cc5db73e5da5392d6ec6d9d01ce65c85e
> >>>> Author: remm <re...@apache.org>
> >>>> AuthorDate: Sun May 5 10:37:05 2019 +0200
> >>>>
> >>>> Make sure timeout elapses before calling a timeout
> >>>>
> >>>> It seems there are extra stream notify as although 0 bytes have
> been
> >>>> allocated only a few ms have passed when there is a failure.
> >>>
> >>> I think something else is going on here. I'm still trying to figure it
> >> out.
> >>
> >> I can't reproduce the test failure - either with the code or some code
> >> written to explicitly test this scenario. However, I do believe I know
> >> what the problem is.
> >>
> >> backLogStreams is a concurrent Map of Stream to int[]. The int[] is a
> >> two element array where the first element is number of bytes the stream
> >> requires and the second is the number allocated.
> >>
> >> I believe the issue occurs as follows:
> >> - Thread A requests more bytes for Stream A than are available in the
> >> connection window
> >> - Stream A is placed into the backlog
> >> - Thread A enters streamA.wait()
> >> - Thread B processes a Window update message
> >> - Thread B allocates some bytes to streamA
> >> - Thread B calls streamA.notify()
> >> - Thread A exits the wait but, because the elements of the int[] are not
> >> volatile, it does not see the window update
> >> - Thread A treats existing the wait without an allocation as a timeout
> >>
> >> I've left out the obtaining and releasing of locks on streamA and the
> >> Http2UpgradeHandler for clarity but I'll note that some reads of the
> >> allocation occur outside of any lock
> >>
> >> The above description is consistent with a known failure trace:
> >>
> >>
> https://ci.apache.org/projects/tomcat/tomcat9/logs/4288/TEST-org.apache.coyote.http2.TestHttp2Section_5_3.NIO2.txt
> >>
> >> My plan is as follows:
> >> - revert the "check it has really timed out fix"
> >> - modify the access to the allocation so that updates to the allocation
> >> are guaranteed to be visible after the wait() exits
> >>
> >
> > I agree there's something wrong, but the current algorithm may not be
> > robust enough because anything notifying the stream object will break it.
>
> I think we have / had multiple bugs here. That hasn't been helping.
>
> > From the logs, the problem (looking only at test 5_3) is with stream 19.
> > When the test passes, the stream was never actually backloged. When it
> > fails, it was and the window update frame read does not cause the backlog
> > release (so when Stream.incrementWindowSize does notifyAll, it breaks).
>
> I see what you mean. Waiting on the stream object for the stream window
> update and the connection window update isn't going to work.
>
> If you can see a solution - do let me know. My instinct is that this is
> going to be a tricky one to fix.
>
> Is this a regression that needs to be fixed? Or should I go ahead with
> the releases. Personally, I'm leaning towards going ahead.
>
I'm not sure. I don't think it happens without async [for whatever timing
reason].
Rémy
Re: [tomcat] branch master updated: Make sure timeout elapses before
calling a timeout
Posted by Mark Thomas <ma...@apache.org>.
On 10/05/2019 16:26, Rémy Maucherat wrote:
> On Fri, May 10, 2019 at 11:14 AM Mark Thomas <ma...@apache.org> wrote:
>
>> On 09/05/2019 21:53, Mark Thomas wrote:
>>> On 05/05/2019 09:37, remm@apache.org wrote:
>>>> This is an automated email from the ASF dual-hosted git repository.
>>>>
>>>> remm pushed a commit to branch master
>>>> in repository https://gitbox.apache.org/repos/asf/tomcat.git
>>>>
>>>>
>>>> The following commit(s) were added to refs/heads/master by this push:
>>>> new 6232d82 Make sure timeout elapses before calling a timeout
>>>> 6232d82 is described below
>>>>
>>>> commit 6232d82cc5db73e5da5392d6ec6d9d01ce65c85e
>>>> Author: remm <re...@apache.org>
>>>> AuthorDate: Sun May 5 10:37:05 2019 +0200
>>>>
>>>> Make sure timeout elapses before calling a timeout
>>>>
>>>> It seems there are extra stream notify as although 0 bytes have been
>>>> allocated only a few ms have passed when there is a failure.
>>>
>>> I think something else is going on here. I'm still trying to figure it
>> out.
>>
>> I can't reproduce the test failure - either with the code or some code
>> written to explicitly test this scenario. However, I do believe I know
>> what the problem is.
>>
>> backLogStreams is a concurrent Map of Stream to int[]. The int[] is a
>> two element array where the first element is number of bytes the stream
>> requires and the second is the number allocated.
>>
>> I believe the issue occurs as follows:
>> - Thread A requests more bytes for Stream A than are available in the
>> connection window
>> - Stream A is placed into the backlog
>> - Thread A enters streamA.wait()
>> - Thread B processes a Window update message
>> - Thread B allocates some bytes to streamA
>> - Thread B calls streamA.notify()
>> - Thread A exits the wait but, because the elements of the int[] are not
>> volatile, it does not see the window update
>> - Thread A treats existing the wait without an allocation as a timeout
>>
>> I've left out the obtaining and releasing of locks on streamA and the
>> Http2UpgradeHandler for clarity but I'll note that some reads of the
>> allocation occur outside of any lock
>>
>> The above description is consistent with a known failure trace:
>>
>> https://ci.apache.org/projects/tomcat/tomcat9/logs/4288/TEST-org.apache.coyote.http2.TestHttp2Section_5_3.NIO2.txt
>>
>> My plan is as follows:
>> - revert the "check it has really timed out fix"
>> - modify the access to the allocation so that updates to the allocation
>> are guaranteed to be visible after the wait() exits
>>
>
> I agree there's something wrong, but the current algorithm may not be
> robust enough because anything notifying the stream object will break it.
I think we have / had multiple bugs here. That hasn't been helping.
> From the logs, the problem (looking only at test 5_3) is with stream 19.
> When the test passes, the stream was never actually backloged. When it
> fails, it was and the window update frame read does not cause the backlog
> release (so when Stream.incrementWindowSize does notifyAll, it breaks).
I see what you mean. Waiting on the stream object for the stream window
update and the connection window update isn't going to work.
If you can see a solution - do let me know. My instinct is that this is
going to be a tricky one to fix.
Is this a regression that needs to be fixed? Or should I go ahead with
the releases. Personally, I'm leaning towards going ahead.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: [tomcat] branch master updated: Make sure timeout elapses before
calling a timeout
Posted by Rémy Maucherat <re...@apache.org>.
On Fri, May 10, 2019 at 11:14 AM Mark Thomas <ma...@apache.org> wrote:
> On 09/05/2019 21:53, Mark Thomas wrote:
> > On 05/05/2019 09:37, remm@apache.org wrote:
> >> This is an automated email from the ASF dual-hosted git repository.
> >>
> >> remm pushed a commit to branch master
> >> in repository https://gitbox.apache.org/repos/asf/tomcat.git
> >>
> >>
> >> The following commit(s) were added to refs/heads/master by this push:
> >> new 6232d82 Make sure timeout elapses before calling a timeout
> >> 6232d82 is described below
> >>
> >> commit 6232d82cc5db73e5da5392d6ec6d9d01ce65c85e
> >> Author: remm <re...@apache.org>
> >> AuthorDate: Sun May 5 10:37:05 2019 +0200
> >>
> >> Make sure timeout elapses before calling a timeout
> >>
> >> It seems there are extra stream notify as although 0 bytes have been
> >> allocated only a few ms have passed when there is a failure.
> >
> > I think something else is going on here. I'm still trying to figure it
> out.
>
> I can't reproduce the test failure - either with the code or some code
> written to explicitly test this scenario. However, I do believe I know
> what the problem is.
>
> backLogStreams is a concurrent Map of Stream to int[]. The int[] is a
> two element array where the first element is number of bytes the stream
> requires and the second is the number allocated.
>
> I believe the issue occurs as follows:
> - Thread A requests more bytes for Stream A than are available in the
> connection window
> - Stream A is placed into the backlog
> - Thread A enters streamA.wait()
> - Thread B processes a Window update message
> - Thread B allocates some bytes to streamA
> - Thread B calls streamA.notify()
> - Thread A exits the wait but, because the elements of the int[] are not
> volatile, it does not see the window update
> - Thread A treats existing the wait without an allocation as a timeout
>
> I've left out the obtaining and releasing of locks on streamA and the
> Http2UpgradeHandler for clarity but I'll note that some reads of the
> allocation occur outside of any lock
>
> The above description is consistent with a known failure trace:
>
> https://ci.apache.org/projects/tomcat/tomcat9/logs/4288/TEST-org.apache.coyote.http2.TestHttp2Section_5_3.NIO2.txt
>
> My plan is as follows:
> - revert the "check it has really timed out fix"
> - modify the access to the allocation so that updates to the allocation
> are guaranteed to be visible after the wait() exits
>
I agree there's something wrong, but the current algorithm may not be
robust enough because anything notifying the stream object will break it.
From the logs, the problem (looking only at test 5_3) is with stream 19.
When the test passes, the stream was never actually backloged. When it
fails, it was and the window update frame read does not cause the backlog
release (so when Stream.incrementWindowSize does notifyAll, it breaks).
The trace is:
at
org.apache.coyote.http2.AbstractStream.incrementWindowSize(AbstractStream.java:121)
at org.apache.coyote.http2.Stream.incrementWindowSize(Stream.java:251)
at
org.apache.coyote.http2.Http2UpgradeHandler.incrementWindowSize(Http2UpgradeHandler.java:1533)
at
org.apache.coyote.http2.Http2AsyncUpgradeHandler.incrementWindowSize(Http2AsyncUpgradeHandler.java:39)
at
org.apache.coyote.http2.Http2Parser.readWindowUpdateFrame(Http2Parser.java:416)
at
org.apache.coyote.http2.Http2AsyncParser$FrameCompletionHandler.completed(Http2AsyncParser.java:269)
Rémy
Re: [tomcat] branch master updated: Make sure timeout elapses before
calling a timeout
Posted by Mark Thomas <ma...@apache.org>.
On 09/05/2019 21:53, Mark Thomas wrote:
> On 05/05/2019 09:37, remm@apache.org wrote:
>> This is an automated email from the ASF dual-hosted git repository.
>>
>> remm pushed a commit to branch master
>> in repository https://gitbox.apache.org/repos/asf/tomcat.git
>>
>>
>> The following commit(s) were added to refs/heads/master by this push:
>> new 6232d82 Make sure timeout elapses before calling a timeout
>> 6232d82 is described below
>>
>> commit 6232d82cc5db73e5da5392d6ec6d9d01ce65c85e
>> Author: remm <re...@apache.org>
>> AuthorDate: Sun May 5 10:37:05 2019 +0200
>>
>> Make sure timeout elapses before calling a timeout
>>
>> It seems there are extra stream notify as although 0 bytes have been
>> allocated only a few ms have passed when there is a failure.
>
> I think something else is going on here. I'm still trying to figure it out.
I can't reproduce the test failure - either with the code or some code
written to explicitly test this scenario. However, I do believe I know
what the problem is.
backLogStreams is a concurrent Map of Stream to int[]. The int[] is a
two element array where the first element is number of bytes the stream
requires and the second is the number allocated.
I believe the issue occurs as follows:
- Thread A requests more bytes for Stream A than are available in the
connection window
- Stream A is placed into the backlog
- Thread A enters streamA.wait()
- Thread B processes a Window update message
- Thread B allocates some bytes to streamA
- Thread B calls streamA.notify()
- Thread A exits the wait but, because the elements of the int[] are not
volatile, it does not see the window update
- Thread A treats existing the wait without an allocation as a timeout
I've left out the obtaining and releasing of locks on streamA and the
Http2UpgradeHandler for clarity but I'll note that some reads of the
allocation occur outside of any lock
The above description is consistent with a known failure trace:
https://ci.apache.org/projects/tomcat/tomcat9/logs/4288/TEST-org.apache.coyote.http2.TestHttp2Section_5_3.NIO2.txt
My plan is as follows:
- revert the "check it has really timed out fix"
- modify the access to the allocation so that updates to the allocation
are guaranteed to be visible after the wait() exits
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: [tomcat] branch master updated: Make sure timeout elapses before
calling a timeout
Posted by Mark Thomas <ma...@apache.org>.
On 05/05/2019 09:37, remm@apache.org wrote:
> This is an automated email from the ASF dual-hosted git repository.
>
> remm pushed a commit to branch master
> in repository https://gitbox.apache.org/repos/asf/tomcat.git
>
>
> The following commit(s) were added to refs/heads/master by this push:
> new 6232d82 Make sure timeout elapses before calling a timeout
> 6232d82 is described below
>
> commit 6232d82cc5db73e5da5392d6ec6d9d01ce65c85e
> Author: remm <re...@apache.org>
> AuthorDate: Sun May 5 10:37:05 2019 +0200
>
> Make sure timeout elapses before calling a timeout
>
> It seems there are extra stream notify as although 0 bytes have been
> allocated only a few ms have passed when there is a failure.
I think something else is going on here. I'm still trying to figure it out.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org