New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"Slow" client causes IllegalStateException #730

Closed
poutsma opened this Issue Jul 15, 2016 · 9 comments

Comments

Projects
None yet
4 participants
@poutsma

poutsma commented Jul 15, 2016

We have come across an issue with the Servlet 3.1 async support in Jetty 9.3.10.v20160621. When a (non-Jetty) HTTP client is "slow" in sending the request body, Jetty will end up in an illegal state, with the following exception:

java.lang.IllegalStateException: state=ASYNC
    at org.eclipse.jetty.server.HttpOutput.run(HttpOutput.java:944)
    at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1286)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:427)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:253)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
    at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
    at java.lang.Thread.run(Thread.java:745)

It seems a bit strange that a slow client has effect on the servlet output, but the issue is 100% reproducible in our tests, on both Mac OS and Linux.

Here is a sample project that demonstrates the issue: https://github.com/poutsma/jetty-async-issue.

That project contains a ServerDriver that starts a Jetty Server with the AsyncIssueServlet, which uses the ReadListener and WriteListener API to consume the input. It also contains a ClientDriver which uses HttpURLConnection to send data. The only thing non-standard in both is the Thread.sleep statement in the client, making it slower in sending out its request. Both driver classes have a main method that starts them up.

Let me know if you need any further information.

@sbordet

This comment has been minimized.

Show comment
Hide comment
@sbordet

sbordet Jul 15, 2016

Contributor

Your code is not correct.

In onDataAvailable() you use a buffer that is created outside the loop.
You read into that buffer, then you write it. However, this write may be pending.
You loop, check if you are read ready, you are, therefore you read more into that buffer, whose write may not be completed. This will corrupt the data you are writing.

In onDataAvailable() the else branch for out.isReady() accumulates the bytes into a builder that is not written to the output.

onWritePossible() can potentially be an infinite loop. You check for isReady() then you flush() and after the flush you may be ready again, thus looping infinitely.

I understand this was a minimal code to reproduce the issue, just wanted to point out incorrectnesses that you may have missed.

Contributor

sbordet commented Jul 15, 2016

Your code is not correct.

In onDataAvailable() you use a buffer that is created outside the loop.
You read into that buffer, then you write it. However, this write may be pending.
You loop, check if you are read ready, you are, therefore you read more into that buffer, whose write may not be completed. This will corrupt the data you are writing.

In onDataAvailable() the else branch for out.isReady() accumulates the bytes into a builder that is not written to the output.

onWritePossible() can potentially be an infinite loop. You check for isReady() then you flush() and after the flush you may be ready again, thus looping infinitely.

I understand this was a minimal code to reproduce the issue, just wanted to point out incorrectnesses that you may have missed.

@sbordet

This comment has been minimized.

Show comment
Hide comment
@sbordet

sbordet Jul 15, 2016

Contributor

However, I also think we have a bug, standby for analysis.

Contributor

sbordet commented Jul 15, 2016

However, I also think we have a bug, standby for analysis.

@sbordet

This comment has been minimized.

Show comment
Hide comment
@sbordet

sbordet Jul 15, 2016

Contributor

@gregw:

Jetty calls onDataAvailable(), the Servlet reads some, then write some, then exits the loop because it's not read ready.

At that point, the HttpChannel loop calls HttpChannelState.unhandle() whose _state == ASYNC_IO and _async == STARTED and the state is changed to _state = ASYNC_IO and action = WRITE_CALLBACK.

Because the last operation on HttpOutput was a write, its _state == ASYNC; it is switched back to READY when isReady() is called.

However, HttpChannel found a WRITE_CALLBACK action after returning from onDataAvailable(), so it invokes HttpOutput.run() throwing the exception reported above.

I think we should accept the fact that HttpOutput.run() can be called with _state == ASYNC due to a previous write from onDataAvailable() (or even onAllDataRead()).

Your thoughts ?

Contributor

sbordet commented Jul 15, 2016

@gregw:

Jetty calls onDataAvailable(), the Servlet reads some, then write some, then exits the loop because it's not read ready.

At that point, the HttpChannel loop calls HttpChannelState.unhandle() whose _state == ASYNC_IO and _async == STARTED and the state is changed to _state = ASYNC_IO and action = WRITE_CALLBACK.

Because the last operation on HttpOutput was a write, its _state == ASYNC; it is switched back to READY when isReady() is called.

However, HttpChannel found a WRITE_CALLBACK action after returning from onDataAvailable(), so it invokes HttpOutput.run() throwing the exception reported above.

I think we should accept the fact that HttpOutput.run() can be called with _state == ASYNC due to a previous write from onDataAvailable() (or even onAllDataRead()).

Your thoughts ?

sbordet added a commit that referenced this issue Jul 15, 2016

Issue #730 - "Slow" client causes IllegalStateException.
Fixed by allowing state ASYNC to call onWritePossible().
@sbordet

This comment has been minimized.

Show comment
Hide comment
@sbordet

sbordet Jul 15, 2016

Contributor

@gregw I have committed a fix to `HttpOutput', please review.

Contributor

sbordet commented Jul 15, 2016

@gregw I have committed a fix to `HttpOutput', please review.

@sbordet sbordet added the Bug label Jul 15, 2016

rstoyanchev added a commit to spring-projects/spring-framework that referenced this issue Jul 15, 2016

@gregw

This comment has been minimized.

Show comment
Hide comment
@gregw

gregw Jul 20, 2016

Contributor

@sbordet I've not looked in detail yet, but I think your change broke something in 9.4.x, which I noticed yesterday as a noisy broken unit test and I committed 86ff9f9 as a fix. Need to consider both together.

I feel like I'm missing all the code I need to analyse this, but my concern is that output.isReady() should be called before all writes. Only if it has returned true can a write be done and only if it returns false should onWritePossible eventually be called.... but let me look more and see if that applies here.

Contributor

gregw commented Jul 20, 2016

@sbordet I've not looked in detail yet, but I think your change broke something in 9.4.x, which I noticed yesterday as a noisy broken unit test and I committed 86ff9f9 as a fix. Need to consider both together.

I feel like I'm missing all the code I need to analyse this, but my concern is that output.isReady() should be called before all writes. Only if it has returned true can a write be done and only if it returns false should onWritePossible eventually be called.... but let me look more and see if that applies here.

@gregw

This comment has been minimized.

Show comment
Hide comment
@gregw

gregw Jul 20, 2016

Contributor

So this is one of very many edge cases/races.

The call to onWritePossible is scheduled because setWriteListener has been called, but a write is done prior to that call, so a write may not actually be possible!

I think this is just a specific example of a race that can occur between onWritePossible being scheduled because of a false isReady return and some other thread just calling write.

I think the solution is that onWritePossible should still be called and if the other write has made a write not possible, the onWritePossible implementation should still be checking isReady() before every write.

So I think your fix is good... and I think my fix in 9.4.x is also good (similar solution different place), but I need to ponder a bit more to be 100% sure

Contributor

gregw commented Jul 20, 2016

So this is one of very many edge cases/races.

The call to onWritePossible is scheduled because setWriteListener has been called, but a write is done prior to that call, so a write may not actually be possible!

I think this is just a specific example of a race that can occur between onWritePossible being scheduled because of a false isReady return and some other thread just calling write.

I think the solution is that onWritePossible should still be called and if the other write has made a write not possible, the onWritePossible implementation should still be checking isReady() before every write.

So I think your fix is good... and I think my fix in 9.4.x is also good (similar solution different place), but I need to ponder a bit more to be 100% sure

gregw added a commit that referenced this issue Jul 20, 2016

Calling onWritePossible in race with write #730
This commit cleans up the combination of the prior fix to #730 in 0433a8c
and the prior cleanup in 86ff9f9.   More comments have been added to explain.
@gregw

This comment has been minimized.

Show comment
Hide comment
@gregw

gregw Jul 20, 2016

Contributor

I think @sbordet's fix is good for 9.3.x and our combined fixes are good for 9.4.x. However I just committed a bit more of a cleanup and more comment descriptions to 9.4.x.

My lingering concern is the javadoc for onWritePossible which includes the statement:

this method will be invoked by the container the first time when it is possible to write data

So if we are calling onWritePossible even though onDataAvailable or another thread may have done a write that makes it not possible to write data. So the first time when it is possible to write data is before onDataAvailable is called, but then if we reverse the order we get the same problem in reverse if onWritePossible reads data.

I think we are doing the best that is possible and I will raise an issue on the servlet spec to clarify the language.

Contributor

gregw commented Jul 20, 2016

I think @sbordet's fix is good for 9.3.x and our combined fixes are good for 9.4.x. However I just committed a bit more of a cleanup and more comment descriptions to 9.4.x.

My lingering concern is the javadoc for onWritePossible which includes the statement:

this method will be invoked by the container the first time when it is possible to write data

So if we are calling onWritePossible even though onDataAvailable or another thread may have done a write that makes it not possible to write data. So the first time when it is possible to write data is before onDataAvailable is called, but then if we reverse the order we get the same problem in reverse if onWritePossible reads data.

I think we are doing the best that is possible and I will raise an issue on the servlet spec to clarify the language.

@gregw

This comment has been minimized.

Show comment
Hide comment
@gregw

gregw Jul 20, 2016

Contributor
Contributor

gregw commented Jul 20, 2016

@joakime

This comment has been minimized.

Show comment
Hide comment
@joakime

joakime Nov 1, 2016

Member

Closing, as this bug (for Jetty 9.3.x) seems complete.

If there is a larger concern for Jetty 9.4.x, lets open a new issue to track that.

@gregw please open a new issue against 9.4.x if you think its needed.

Member

joakime commented Nov 1, 2016

Closing, as this bug (for Jetty 9.3.x) seems complete.

If there is a larger concern for Jetty 9.4.x, lets open a new issue to track that.

@gregw please open a new issue against 9.4.x if you think its needed.

@joakime joakime closed this Nov 1, 2016

@joakime joakime added this to the 9.3.x milestone Nov 1, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment