More helpful warning message than "Closed while Pending/Unready" #2689
Comments
|
Thanks for filing this. |
|
You're welcome! Feel free to use my Stack Overflow question and answer them as you wish. |
|
From the stackoverflow.com question ( copied here with permission from @palacsint ) Question: Understanding Jetty's “Closed while Pending/Unready” warningWe have an asynchronous servlet which produces the following warning log from Jetty: After enabling debug logs I got the following stacktrace: It did not help too much. The warning comes only after Jetty calls the How can I reproduce this warning with a sample servlet-client code? I would like to understand this issue in a simpler environment than our production code to be able to fix the production one afterwards. How should a sample servlet behave? Is it possible to reproduce that with an Apache Commons HttpClient client side in the same JUnit test? (That would be great for writing an integration test without complicated network hacking, like I have tried a few things to implement a sample async servlet and client without success. I don't think that attaching this code would help too much but I can do that if anyone interested. Jetty version: 9.4.8.v20171121 update (2018-06-27): Reflecting to @joakim Erdfelt's helpful answer, I have not found any public class QueuePollServlet extends HttpServlet {
public QueuePollServlet() {
}
@Override
protected void doPost(final HttpServletRequest req, final HttpServletResponse resp)
throws ServletException, IOException {
resp.setContentType(MediaType.OCTET_STREAM.type());
resp.setStatus(HttpServletResponse.SC_OK);
resp.flushBuffer();
final AsyncContext async = req.startAsync();
async.setTimeout(30_000);
final ServletOutputStream output = resp.getOutputStream();
final QueueWriteListener writeListener = new QueueWriteListener(async, output);
async.addListener(writeListener);
output.setWriteListener(writeListener);
}
private static class QueueWriteListener implements AsyncListener, WriteListener {
private final AsyncContext asyncContext;
private final ServletOutputStream output;
public QueueWriteListener(final AsyncContext asyncContext, final ServletOutputStream output) {
this.asyncContext = checkNotNull(asyncContext, "asyncContext cannot be null");
this.output = checkNotNull(output, "output cannot be null");
}
@Override
public void onWritePossible() throws IOException {
writeImpl();
}
private synchronized void writeImpl() throws IOException {
while (output.isReady()) {
final byte[] message = getNextMessage();
if (message == null) {
output.flush();
return;
}
output.write(message);
}
}
private void completeImpl() {
asyncContext.complete();
}
public void dataArrived() {
try {
writeImpl();
} catch (IOException e) {
...
}
}
public void noMoreBuffers() {
completeImpl();
}
@Override
public void onTimeout(final AsyncEvent event) throws IOException {
completeImpl();
}
@Override
public void onError(final Throwable t) {
logger.error("Writer.onError", t);
completeImpl();
}
...
}
}A probable race condition:
Could this scenario cause the update (2018-06-28): We also have a similar @Override
public void onError(final Throwable t) {
logger.error("Writer.onError", t);
completeImpl();
}Anyway, there is no Troubleshooting / ResolutionIt is possible to reproduce the case READY:
if (!_state.compareAndSet(OutputState.READY, OutputState.PENDING))
continue;
// put a breakpoint herecase STREAM:
// put a breakpiont here
if (!_out.isClosed())
getOutputStream().close();
break;Steps to reproduce:
So, actually it's Jetty who closes the output stream on this (Jetty 9.4.8.v20171121) stack: Making
Unfortunately, after Furthermore, The final implementation is something similar: @Override
protected void doPost(final HttpServletRequest req, final HttpServletResponse resp)
throws ServletException, IOException {
resp.setContentType(MediaType.OCTET_STREAM.type());
resp.setStatus(HttpServletResponse.SC_OK);
resp.setBufferSize(4096);
resp.flushBuffer();
final AsyncContext async = req.startAsync();
async.setTimeout(5_000); // millis
final ServletOutputStream output = resp.getOutputStream();
final QueueWriteListener writeListener = new QueueWriteListener(async, output);
async.addListener(writeListener);
output.setWriteListener(writeListener);
}
private static class QueueWriteListener implements AsyncListener, WriteListener {
private static final Logger logger = LoggerFactory.getLogger(QueueWriteListener.class);
private final AsyncContext asyncContext;
private final ServletOutputStream output;
@GuardedBy("this")
private boolean completed = false;
public QueueWriteListener(final AsyncContext asyncContext, final ServletOutputStream output) {
this.asyncContext = checkNotNull(asyncContext, "asyncContext cannot be null");
this.output = checkNotNull(output, "output cannot be null");
}
@Override
public void onWritePossible() throws IOException {
writeImpl();
}
private synchronized void writeImpl() throws IOException {
if (completed) {
return;
}
while (output.isReady()) {
final byte[] message = getNextMessage();
if (message == null) {
output.flush();
return;
}
output.write(message);
}
}
private synchronized void completeImpl() {
// also stops DataFeederThread to call bufferArrived
completed = true;
asyncContext.complete();
}
@Override
public void onError(final Throwable t) {
logger.error("Writer.onError", t);
completeImpl();
}
public void dataArrived() {
try {
writeImpl();
} catch (RuntimeException | IOException e) {
...
}
}
public void noMoreData() {
completeImpl();
}
@Override
public synchronized void onComplete(final AsyncEvent event) throws IOException {
completed = true; // might not needed but does not hurt
}
@Override
public synchronized void onTimeout(final AsyncEvent event) throws IOException {
completeImpl();
}
@Override
public void onError(final AsyncEvent event) throws IOException {
logger.error("onError", event.getThrowable());
}
...
} |
|
See new stackoverflow issue (from same OP) ... https://stackoverflow.com/questions/51560975/closed-while-pending-unready-warnings-from-jetty |
|
@gregw this issue could use your eyes (when you get back from vacation) |
|
I patched our Jetty lib with the following to make sure I'm debugging the right servlet: (Feel free to use it for anything.) |
|
If you are using the Request object like that, you might want to make sure that the request wasn't recycled (ie: you are not looking at an old/invalid request). |
|
Perhaps you want to just dump like this ... Request request = _channel.getRequest();
Response response = _channel.getResponse();
IOException ex = new IOException("Closed while Pending/Unready, channel=" + _channel + ", request=" + request + ", response=" + response + ", HttpOutput=" + this);That will show ...
|
|
Having a quick look at this whilst on a train.... Essentially it is a race between a jetty managed thread completing the request due to a AsyncContext timeout vs a non jetty managed thread calling write on the output stream. This is just a natural race that will exist in asynchronous IO programming and we cannot avoid the race, but just have to handle it as best as possible. Best handling is to ensure that we are atomic in the decision if the write or complete call "wins", which I think we are.... but I will triple check the code just in case when on a real machine... but nothing I see in this report nor elsewhere suggests that we have a problem. In this case, the timeout code "won" the race, so the write was correct in failing. But is there anything we can do to help the writer avoid the problem or get a better message? Well we can't fix in So could we have a better exception message? Probably... but the issue is that this code can be miss-used in so many different ways in many different calling patterns with many different races etc. So it is hard for the code to look at the illegalState and from the trenches diagnose exactly which of the nasty race conditions it is in. I think best practise around this is for implementations to be written in a way to acknowledge that there is an |
|
@joakime: Thank you, I'll try that! Anyway, I have not found any call of this |
|
You also need to add some mutual exclusion (locks or synchronize or correct
usage of CAS references) if you are using non jetty threads. Jetty ensures
only a single thread is dispatched for a request, but if you are using
other threads, they need to be serialized with any state changed.
Cheers
…On Sat., 28 Jul. 2018, 13:03 Miklós Karakó, ***@***.***> wrote:
@joakime <https://github.com/joakime>: Thank you, I'll try that!
@gregw <https://github.com/gregw>: If I understand correctly, I should
set the completed flag in onErrormethod too, for example:
@OverRide
public synchronized void onError(final AsyncEvent event) throws IOException {
logger.error("onError", event.getThrowable());
completed = true;
}
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
<#2689 (comment)>,
or mute the thread
<https://github.com/notifications/unsubscribe-auth/AAEUrTgoFLOq0HRetajfAR6ZtvebbK4fks5uLEUSgaJpZM4U_Fg7>
.
|
|
I could think about a case when our DFT (data feeder thread) runs If yes, how can I fix that? Our DFT waits for events, so it's usual that it does not have any data for a while. Blocking for data in
I think the current or the more detailed error message (suggested by @joakime) is fine but some documentation and code examples about how to do it correctly which I really miss. (Unfortunately I have not found any on the web.) This makes me wonder whether our case with the separate data feeder thread is a valid usecase for async servlets at all. |
|
I've just found the In this way writing always will happen on a Jetty thread and I probably get rid of the "Closed while" warnings completely. Or does it have similar race conditions? |
|
Firstly, it's not really a good idea to put the request URL into any exception throw. Exception messages often get put into error page responses and URLs are user supplied data, so suddenly you have a user able to directly provide content for a response page. Jetty's error pages protect against cross site scripting, but an application supplied error page might not be as rigorous... hence we rarely put user supplied data in the exception method.. rather we put it in logged debugs or warnings instead. For the mutual exclusion, the jetty called methods are all mutually excluded from each other, but not from an arbitrary application thread. AsyncContext.dispatch() can be used to essentially reply the request in a call that is also mutually exclusive, so that would be one way to achieve mutual exclusion... however re-entering the whole servlet request can be a bit heavy weight... specially if you have a lot of filters. Instead, you could simply synchronize or have a lock on all the methods, so that you hold that lock while in a |
Good point, thanks!
If I'm right the code above does exactly this. It checks the
In this setup we only have a small filter, so I'm playing with that but it will take a while to get feedback from production. |
|
I was able to reproduce the warning with this code: And with a slow Result: Things to notice:
|
|
So, the warning is reasonable. Is there way I can fix this as a Jetty user? At least log a more descriptive warning message for ops people or increment a monitored JMX counter? Shouldn't Jetty call |
|
@palacsint Yes indeed Jetty should be calling the onError callbacks before trying the close. This definitely now looks like a Jetty bug... looking some more... |
|
@sbordet Need to hangout on this one. But in this case, the context times out and there is a pending write, I think we should error the write.... but it is really unclear when we should do this? Before calling the AsyncContext Listener(s) or only if the listeners do nothing and the container has to act? I think it has to be before the listeners, as they can't really do anything if there are outstanding reads or writes. |
|
@palacsint for now, you might want to configure a connector idleTimeout to be shorter than your async timeout. |
Signed-off-by: Greg Wilkins <gregw@webtide.com>
|
@palacsint I have created a branch and a PR with a fix for this issue. Any AsyncContext errors (including timeout) are now firstly delivered to any outstanding async IO operation. It would be good if you could checkout and built that branch to confirm it fixes the problem as you see it. |
Thanks, that fixed the PoC code above, it does not log "Closed while Pending/Unready" and calls my |
I have also tested that pull request and it seems good. I got this log at the end of the request: (I was able to test it only with the PoC code above. Pushing into production - and testing there - probably will not happen until a new Jetty release which contains the fix.) |
|
I think our thinking has come full circle and that we are now no longer inclined to link the AsyncContext timeout to failing asyncIO operations. There is just no meaningful way to link these events in all circumstances. Essentially the problem is that if AsyncContext does timeout with an outstanding async write, then the exception is correct! There is a pending write! Thus we now think this is really a verbosity problem. If the application attempts an operation, they should see that exception. If the container is doing the close, at the very least it should suppress the bulk of that exception in logging, but it could also error the write during container close rather than throw and log the exception. New PR coming... |
|
Error handling significantly reworked with #3912 so closing this. Please reopen if verbosity still not right. |
I run into a not too helpful "Closed while Pending/Unready" warning message from Jetty which takes a while to debug and fix (details are here: https://stackoverflow.com/q/51014946/843804). It turned out that (in my case) Jetty closes the output stream, so "Writing after AsyncContext.complete()" (or "Closed while Pending/Unready or writing after AsyncContext.complete()") error message would be more appropriate here.
Furthermore, I've not found too much real world examples on the web for async servlets which get data from a non-Jetty thread. So, an official one also would be great. (See my answer on the linked Stack Overflow question above for our code: https://stackoverflow.com/a/51104868/843804).
The text was updated successfully, but these errors were encountered: