Understanding Jetty's “Closed while Pending/Un

问题:

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:

1. DataFeederThread: calls dataArrived() -> writeImpl(), then it gets that output.isReady() is true.
2. Jetty calls onTimeout() which completes the context.
3. 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()

回答1:

It is possible to reproduce the Closed while Pending/Unready warning with some manual debugging and a plain curl 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.

1. The first breakpoint is in the HttpOutput.write() method right after it changes its state from READY to PENDING:

   case READY:
       if (!_state.compareAndSet(OutputState.READY, OutputState.PENDING))
           continue;
       // put a breakpoint here
   

2. The second one in Response.closeOutput():

   case STREAM:
       // put a breakpiont here
       if (!_out.isClosed())
           getOutputStream().close();
       break;
   

Steps to reproduce:

1. [JettyThread1] Calls QueueWriteListener.onWritePossible() which writes a few bytes to the output then returns (as its input buffer is empty).
2. Wait for the onTimeout event.
3. [JettyThread2] HttpChannelState.onTimeout() calls QueueWriteListener.onTimeout() which calls asyncContext.complete().
4. [JettyThread2] HttpChannelState.onTimeout() schedules a dispatch after the async timeout.
5. [JettyThread2] Pauses at the second breakpoint
6. [DFT] DataFeederThread calls writeImpl()
7. [DFT] DataFeederThread calls HttpOutput.write() (it's the output stream)
8. [DFT] HttpOutput.write() changes its state from READY to PENDING
9. [DFT] DataFeederThread pauses here, due to the breakpoint above
10. [JettyThread2] The scheduled dispatch closes the output stream and produces the Closed while Pending/Unready warning.

So, actually it's Jetty who closes the output stream on this (Jetty 9.4.8.v20171121) stack:

Thread [jetty-19] (Suspended)   
    Response.closeOutput() line: 1043   
    HttpChannelOverHttp(HttpChannel).handle() line: 488 
    HttpChannelOverHttp(HttpChannel).run() line: 293    
    QueuedThreadPool.runJob(Runnable) line: 708 
    QueuedThreadPool$2.run() line: 626  
    Thread.run() line: 748  

Making onTimeout() synchronized (as well as writeImpl() is also synchronized) in the listener does not help since the scheduled closing still be able to overlap with writeImpl (from DataFeederThread). Consider this case:

1. [JettyThread1] Calls QueueWriteListener.onWritePossible() which writes a few bytes to the output then returns (as its input buffer is empty).
2. Wait for the onTimeout event.
3. [JettyThread2] HttpChannelState.onTimeout() calls QueueWriteListener.onTimeout() which calls asyncContext.complete().
4. [DFT] DataFeederThread calls writeImpl() (it's blocked since onTimeout has not finished yet)
5. [JettyThread2] QueueWriteListener.onTimeout() finishes
6. [DFT] writeImpl() can run
7. [JettyThread2] HttpChannelState.onTimeout() schedules a dispatch after the async timeout.
8. [JettyThread2] Pauses at the second breakpoint
9. [DFT] DataFeederThread calls HttpOutput.write() (it's the output stream)
10. [DFT] HttpOutput.write() changes its state from READY to PENDING
11. [DFT] DataFeederThread pauses here, due to the breakpoint above
12. [JettyThread2] The scheduled dispatch closes the output stream and produces the Closed while Pending/Unready warning.

Unfortunately, after asnyContext.complete() it is not enough to check output.isReady(). It returns true since Jetty reopens the HttpOutput (see the stack below), so you need a separate flag for that in the listener.

Thread [jetty-13] (Suspended (access of field _state in HttpOutput))    
    HttpOutput.reopen() line: 195   
    HttpOutput.recycle() line: 923  
    Response.recycle() line: 138    
    HttpChannelOverHttp(HttpChannel).recycle() line: 269    
    HttpChannelOverHttp.recycle() line: 83  
    HttpConnection.onCompleted() line: 424  
    HttpChannelOverHttp(HttpChannel).onCompleted() line: 695    
    HttpChannelOverHttp(HttpChannel).handle() line: 493 
    HttpChannelOverHttp(HttpChannel).run() line: 293    
    QueuedThreadPool.runJob(Runnable) line: 708 
    QueuedThreadPool$2.run() line: 626  
    Thread.run() line: 748  

Furthermore, isReady() also returns true when the output is still closed (before recycle/reopen). Related question: isReady() returns true in closed state - why?

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());
    }

    ...
}

update 2018-08-01: Actually it did not fix the warning completely, see: “Closed while Pending/Unready” warnings from Jetty

回答2:

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 using ServletOutputStream.close() verifying that isReady() is true.

Note that it can be desirable to allow a ServletOutputStream.close() at any time, particularly if AsyncContext.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 naked ServletOutputStream.close() is allowed, but the behavior is to abort the response, discarding any pending/unwritten writes on the ServletOutputStream.

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.