We have an asynchronous servlet which produces the following warning log from Jetty:
java.io.IOException: Closed while Pending/Unready
After enabling debug logs I got the following stacktrace:
WARN [jetty-25948] (HttpOutput.java:278) - java.io.IOException: Closed while Pending/Unready
DEBUG [jetty-25948] (HttpOutput.java:279) -
java.io.IOException: Closed while Pending/Unready
at org.eclipse.jetty.server.HttpOutput.close(HttpOutput.java:277) ~[jetty-server.jar:9.4.8.v20171121]
at org.eclipse.jetty.server.Response.closeOutput(Response.java:1044) [jetty-server.jar:9.4.8.v20171121]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:488) [jetty-server.jar:9.4.8.v20171121]
at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:293) [jetty-server.jar:9.4.8.v20171121]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708) [jetty-util.jar:9.4.8.v20171121]
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626) [jetty-util.jar:9.4.8.v20171121]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_151]
It did not help too much.
The warning comes only after Jetty calls the onTimeout()
method of our AsyncListener
. QA sometimes could reproduce it by using kill -9
on the client side application.
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 kill -9
.)
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 close()
call in our code, but found a suspicious missing synchronization. Here is the base of our async poll servlet:
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:
- DataFeederThread: calls
dataArrived()
->writeImpl()
, then it gets thatoutput.isReady()
istrue
. - Jetty calls
onTimeout()
which completes the context. - DataFeederThread: calls
output.write()
in the while loop but found the completed context.
Could this scenario cause the Closed while Pending/Unready
warning or is it another issue?
I am right that making completeImpl()
synchronized
solves the problem or there is something else to care about?
update (2018-06-28):
We also have a similar onError
implementation in QueueWriteListener
as the following snippet:
@Override
public void onError(final Throwable t) {
logger.error("Writer.onError", t);
completeImpl();
}
Anyway, there is no onError
error log around the Closed while Pending/Unready
log message (looking at a two hour timeframe for each), just EOFs like the following ones from our DataFeederThread
:
DEBUG [DataFeederThread] (HttpOutput.java:224) -
org.eclipse.jetty.io.EofException: null
at org.eclipse.jetty.server.HttpConnection$SendCallback.reset(HttpConnection.java:704) ~[jetty-server.jar:9.4.8.v20171121]
at org.eclipse.jetty.server.HttpConnection$SendCallback.access$300(HttpConnection.java:668) ~[jetty-server.jar:9.4.8.v20171121]
at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:526) ~[jetty-server.jar:9.4.8.v20171121]
at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:778) ~[jetty-server.jar:9.4.8.v20171121]
at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:834) ~[jetty-server.jar:9.4.8.v20171121]
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:234) [jetty-server.jar:9.4.8.v20171121]
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:218) [jetty-server.jar:9.4.8.v20171121]
at org.eclipse.jetty.server.HttpOutput.flush(HttpOutput.java:392) [jetty-server.jar:9.4.8.v20171121]
at com.example.QueuePollServlet$QueueWriteListener.writeImpl()
at com.example.QueuePollServlet$QueueWriteListener.dataArrived()
DEBUG [DataFeederThread] (QueuePollServlet.java:217) - messageArrived exception
org.eclipse.jetty.io.EofException: Closed
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:476) ~[jetty-server.jar:9.4.8.v20171121]
at com.example.QueuePollServlet$QueueWriteListener.writeImpl()
at com.example.QueuePollServlet$QueueWriteListener.dataArrived()
You are using Asynchronous I/O from the Servlet Spec and manually closed the Response stream.
Key Fact: A close call implies a write operation.
In the Jetty case, the IOException is telling you that your manual call to the Response stream close has caused an undesired side-effect.
So in Asynchronous I/O mode a call to
ServletOutputStream.isReady()
should have been made prior to usingServletOutputStream.close()
verifying thatisReady()
is true.Note that it can be desirable to allow a
ServletOutputStream.close()
at any time, particularly ifAsyncContext.complete()
has been called on this dispatch.However, if the prior write has not yet completed and/or
ServletOutputStream.isReady()
has not been called, this specific case of a nakedServletOutputStream.close()
is allowed, but the behavior is to abort the response, discarding any pending/unwritten writes on theServletOutputStream
.This is why you get the
IOException("Closed while Pending/Unready")
Now you should ask yourself why are you closing the Response stream? This is not required per the Servlet spec, and is undesired if you ever wanted to use the
RequestDispatcher
to composite multiple Servlets responses together.It is possible to reproduce the
Closed while Pending/Unready
warning with some manual debugging and a plaincurl
client. I have tested it with Jetty 9.4.8.v20171121 and Jetty 9.4.11.v20180605. You need two breakpoints, so it's not easy to reliably reproduce in a test environment.The first breakpoint is in the
HttpOutput.write()
method right after it changes its state fromREADY
toPENDING
:The second one in
Response.closeOutput()
:Steps to reproduce:
QueueWriteListener.onWritePossible()
which writes a few bytes to the output then returns (as its input buffer is empty).HttpChannelState.onTimeout()
callsQueueWriteListener.onTimeout()
which callsasyncContext.complete()
.HttpChannelState.onTimeout()
schedules a dispatch after the async timeout.DataFeederThread
callswriteImpl()
DataFeederThread
callsHttpOutput.write()
(it's the output stream)HttpOutput.write()
changes its state fromREADY
toPENDING
DataFeederThread
pauses here, due to the breakpoint aboveClosed while Pending/Unready
warning.So, actually it's Jetty who closes the output stream on this (Jetty 9.4.8.v20171121) stack:
Making
onTimeout()
synchronized
(as well aswriteImpl()
is alsosynchronized
) in the listener does not help since the scheduled closing still be able to overlap withwriteImpl
(fromDataFeederThread
). Consider this case:QueueWriteListener.onWritePossible()
which writes a few bytes to the output then returns (as its input buffer is empty).HttpChannelState.onTimeout()
callsQueueWriteListener.onTimeout()
which callsasyncContext.complete()
.DataFeederThread
callswriteImpl()
(it's blocked sinceonTimeout
has not finished yet)QueueWriteListener.onTimeout()
finisheswriteImpl()
can runHttpChannelState.onTimeout()
schedules a dispatch after the async timeout.DataFeederThread
callsHttpOutput.write()
(it's the output stream)HttpOutput.write()
changes its state fromREADY
toPENDING
DataFeederThread
pauses here, due to the breakpoint aboveClosed while Pending/Unready
warning.Unfortunately, after
asnyContext.complete()
it is not enough to checkoutput.isReady()
. It returnstrue
since Jetty reopens theHttpOutput
(see the stack below), so you need a separate flag for that in the listener.Furthermore,
isReady()
also returnstrue
when the output is still closed (before recycle/reopen). Related question: isReady() returns true in closed state - why?The final implementation is something similar:
update 2018-08-01: Actually it did not fix the warning completely, see: “Closed while Pending/Unready” warnings from Jetty