Potential infinite loop when request is not fully read

[Marco85Li]

Jetty version
9.4.35.v20201120

Java version
jdk-14.0.1

OS type/version
Win7

Description

During the upload of a large request, if the server application (in an async handler) responds without fully reading the content (e.g. due to timeout), Jetty may enter an infinite loop.

jetty infinite loop.log

[gregw]

So if we understand the logs correctly.... you have:

• called startAsync on the request
• in another thread (not servlet container dispatched one) you do a blocking read... which blocks.
• in yet another thread (also not a servlet container dispatched one) you call AsyncContext.complete()
• chaos and mayhem result

So my first instinct is to say DON'T DO THAT!!!! I'm not sure it is exactly legal to try to complete the async cycle whilst you are still blocked in a read.
But then turning off my instincts, I can't see anything in the API contract that says you can't do that... and even if it is not a good idea, we definitely should not fail so badly if somebody does it.

So I'll try to reproduce this and if my analysis is right, I think the solution is that complete will have to fail any reads (or writes for that matter) that are in progress in other threads.

The problem you will have of course is that once we do that, then the thread that did the read will get an exception and hopefully it will not then try to write the response, as if it does then it may do so whilst the complete is actually writing the response... and response is not a threadsafe object, so if 2 threads are messing with it at the same time, more chaos may result.... but at least that wont be our fault!

So if you can confirm my outline above, I'll proceed to try make a reproduction.

[gregw]

Also did this used to work in earlier releases and had just failed in 9.4.35?

[gregw]

I can reproduce the ReadPendingException from your log, but I then don't see any loop.

java.nio.channels.ReadPendingException
	at org.eclipse.jetty.io.FillInterest.register(FillInterest.java:58)
	at org.eclipse.jetty.io.AbstractEndPoint.fillInterested(AbstractEndPoint.java:362)
	at org.eclipse.jetty.io.AbstractConnection.fillInterested(AbstractConnection.java:134)
	at org.eclipse.jetty.server.HttpConnection.onCompleted(HttpConnection.java:467)
	at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:820)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:368)
	at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:340)
	at org.eclipse.jetty.server.HttpChannelState.runInContext(HttpChannelState.java:1204)
	at org.eclipse.jetty.server.HttpChannelState.complete(HttpChannelState.java:714)
	at org.eclipse.jetty.server.AsyncContextState.complete(AsyncContextState.java:72)
	at org.eclipse.jetty.http.client.ServerTimeoutsTest$BlockingReadAndCompleteHandler.lambda$handle$1(ServerTimeoutsTest.java:1062)
	at java.base/java.lang.Thread.run(Thread.java:834)

We should try to avoid this exception anyway,

[gregw]

The test case is

    @ParameterizedTest
    @ArgumentsSource(TransportProvider.class)
    public void testBlockingReadInOtherThreadThenComplete(Transport transport) throws Exception
    {
        init(transport);
        BlockingReadAndCompleteHandler handler = new BlockingReadAndCompleteHandler();
        scenario.start(handler);

        try /*(StacklessLogging ignore = new StacklessLogging(HttpChannel.class))*/
        {
            DeferredContentProvider contentProvider = new DeferredContentProvider(ByteBuffer.allocate(1));
            CountDownLatch resultLatch = new CountDownLatch(1);
            scenario.client.POST(scenario.newURI())
                .content(contentProvider)
                .send(result ->
                {
                    if (result.getResponse().getStatus() == 299)
                        resultLatch.countDown();
                });

            // Blocking read should error.
            assertTrue(handler.readErrorLatch.await(5, TimeUnit.SECONDS));

            // request should complete without waiting for content.
            assertTrue(handler.readErrorLatch.await(1, TimeUnit.SECONDS));

            // Complete the request.
            contentProvider.close();
            assertTrue(resultLatch.await(5, TimeUnit.SECONDS));
        }
        catch (Exception e)
        {
            throw e;
        }
    }

    private static class BlockingReadAndCompleteHandler extends AbstractHandler
    {
        CountDownLatch readErrorLatch;
        CountDownLatch completeLatch;

        public BlockingReadAndCompleteHandler()
        {
            this.readErrorLatch = new CountDownLatch(1);
            this.completeLatch = new CountDownLatch(1);
        }

        @Override
        public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException
        {
            baseRequest.setHandled(true);
            AsyncContext asyncContext = baseRequest.startAsync();
            ServletInputStream input = request.getInputStream();
            CountDownLatch reading = new CountDownLatch(1);
            new Thread(() ->
            {
                try
                {
                    response.setStatus(289);
                    while (input.read() >= 0)
                    {
                        reading.countDown();
                    }
                }
                catch (IOException x)
                {
                    readErrorLatch.countDown();
                }
            }).start();

            try
            {
                reading.await();
            }
            catch (Exception e)
            {
                throw new ServletException(e);
            }

            new Thread(() ->
            {
                try
                {
                    Thread.sleep(500);
                    response.setStatus(299);
                    asyncContext.complete();
                    completeLatch.countDown();
                }
                catch (InterruptedException x)
                {
                    throw new IllegalStateException(x);
                }
            }).start();
        }
    }

We can make this a little bit better by doing a tryFillInterested in HttpConnection, but that still does not wake up the blocking thread. So HttpInput needs to be told about the completion and fail any outstanding operations.

Of course then there will still be the race between any error handling on the read caller and potentially it might interfere with the next cycle of the recycled response. This demonstrates the danger of writing applications in this style.

[Marco85Li]

We had this occur using the REST Easy framework when a method handling a slow upload asynchronously (@Suspended annotation) goes over the configured timeout and REST Easy forces an error to be sent while data is being read which may trigger a race condition.

We changed the handling of the timeout but this may still be an unexpected behavior.

[gregw]

@Marco85Li Note that the servlet spec allows request and response objects to be recycled and explicitly says that an application is responsible for not using a request/response object passed the end of the natural request/response cycle.

So in this case, it is an error for the REST Easy framework to complete the request when there may be other threads still interacting with it. Specifically if the other thread catches any exception that it receives from the read and then tries to write a response, it may well end up writing a response to the next request.

Now having said that - jetty should not infinite loop - nor behave badly in other ways when it sees a complete whilst a blocking operation is in effect. So we need to improve here, at least with the ReadPendingException. However, we can't reproduce the loop in our testing of this scenario. How sure are you that it is related?

[github-actions]

This issue has been automatically marked as stale because it has been a
full year without activity. It will be closed if no further activity occurs.
Thank you for your contributions.

[lorban]

Since this issue was opened, many bugs were fixed in multiple code area whose impact could solve the reported issue. At least those ones are related:

• Issue #5605 unconsumed input on sendError #5637
• Blocked IO Thread not woken #5605
• Unnecessary blocking in ResourceService #5937
• Improve handling of unconsumed content #6168

Upgrading to the latest 9.4 release should be tried to see if that helps. If that fails, the investigation should be resumed.

@Marco85Li are you still interested in investigating this? Thanks!

[Marco85Li]

@lorban

As you said, different issues have been fixed. We can close this issue as "undetermined".

I'll try to reproduce the issue against the latest released build of the 9.4 branch and, if the loop occurs again, I'll attach new logs and hopefully a code sample.

Regards,
Marco

[lorban]

@Marco85Li Thank you for your feedback. Please do open a new issue if you run into this problem again.