No idle timeout exception when dispatch is delayed

[gregw]

Reported by Daniel Gredler djgredler@gmail.com

The following test indicates that the idle Timeout is not throwing an IOException?

import static java.nio.charset.StandardCharsets.UTF_8;
import java.io.IOException;
import java.io.OutputStreamWriter;
import java.net.InetAddress;
import java.net.Socket;
import java.util.concurrent.TimeoutException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import org.eclipse.jetty.server.NetworkConnector;
import org.eclipse.jetty.server.Request;
import org.eclipse.jetty.server.Server;
import org.eclipse.jetty.server.ServerConnector;
import org.eclipse.jetty.server.handler.AbstractHandler;
import org.eclipse.jetty.util.IO;

public class JettyTimeoutTest
{

    public static void main(String... args) throws Exception
    {

        int port = 8181;
        Server jetty = new Server(port);
        jetty.getBean(ServerConnector.class).setIdleTimeout(10_000);
        jetty.setHandler(new TestHandler());
        jetty.start();

        try (Socket s = new Socket(InetAddress.getByName("localhost"),port))
        {

            String body = "abcdefghijklmnopqrstuvwxyz";

            OutputStreamWriter sw = new OutputStreamWriter(s.getOutputStream(),UTF_8);
            sw.write("POST /foo HTTP/1.0\r\n");
            sw.write("Content-Length: " + body.length() + "\r\n");
            sw.write("Content-Type: application/x-www-form-urlencoded\r\n");
            sw.write("\r\n");
            sw.flush();
            sw.write(body.substring(0,10));
            // Thread.sleep(15_000); // a little longer than the server timeout, which is 10 seconds
            // sw.write(body.substring(10));
            // sw.flush();

            String response = IO.toString(s.getInputStream(),UTF_8);
            System.out.println("Response:");
            System.out.println(response); // 408 response in Jetty <= 9.2.23, empty response in Jetty >= 9.3.0

        }
        finally
        {
            jetty.stop();
        }
    }

    private static class TestHandler extends AbstractHandler
    {

        @Override
        public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response)
            throws IOException
        {

            int status;
            String body;

            try
            {
                status = HttpServletResponse.SC_OK;
                body = IO.toString(request.getInputStream(),UTF_8); // tries to read the entire POST body
            }
            catch (IOException e)
            {
                e.printStackTrace();
                if (e.getCause() instanceof TimeoutException)
                {
                    status = HttpServletResponse.SC_REQUEST_TIMEOUT;
                    body = "HTTP ERROR 408";
                }
                else
                {
                    status = HttpServletResponse.SC_INTERNAL_SERVER_ERROR;
                    body = "HTTP ERROR 500";
                }
            }

            response.setContentType("text/plain");
            response.setStatus(status);
            response.getWriter().write(body);
            baseRequest.setHandled(true);
        }
    }
}

[gregw]

Debug shows the timeout calling onFail in the fillInterest and there is a ReadCB pending, but it does not appear to actually get called?

2017-12-28 11:05:38.298:DBUG:oeji.FillInterest:Scheduler-1229416514: onFail FillInterest@4a5b7f23{AC.ReadCB@7b5c574a{HttpConnection@7b5c574a[p=HttpParser{s=CONTENT,0 of 26},g=HttpGenerator@21121bc4{s=START}]=>HttpChannelOverHttp@342dd722{r=1,c=false,a=IDLE,uri=/foo}<-SocketChannelEndPoint@43de1a99{/127.0.0.1:56630<->/127.0.0.1:8181,OPEN,fill=FI,flush=-,to=10002/10000}{io=1/1,kio=1,kro=1}->HttpConnection@7b5c574a[p=HttpParser{s=CONTENT,0 of 26},g=HttpGenerator@21121bc4{s=START}]=>HttpChannelOverHttp@342dd722{r=1,c=false,a=IDLE,uri=/foo}}}
java.util.concurrent.TimeoutException: Idle timeout expired: 10001/10000 ms
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:166)
	at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
2017-12-28 11:05:38.299:DBUG:oejh.HttpParser:Scheduler-1229416514: close HttpParser{s=CONTENT,0 of 26}
2017-12-28 11:05:38.299:DBUG:oejh.HttpParser:Scheduler-1229416514: CONTENT --> CLOSE
2017-12-28 11:05:38.299:DBUG:oeji.AbstractConnection:Scheduler-1229416514: HttpConnection@7b5c574a[p=HttpParser{s=CLOSE,0 of 26},g=HttpGenerator@21121bc4{s=START}]=>HttpChannelOverHttp@342dd722{r=1,c=false,a=IDLE,uri=/foo}<-SocketChannelEndPoint@43de1a99{/127.0.0.1:56630<->/127.0.0.1:8181,OPEN,fill=-,flush=-,to=10003/10000}{io=1/1,kio=1,kro=1}->HttpConnection@7b5c574a[p=HttpParser{s=CLOSE,0 of 26},g=HttpGenerator@21121bc4{s=START}]=>HttpChannelOverHttp@342dd722{r=1,c=false,a=IDLE,uri=/foo} onFillInterestedFailed java.util.concurrent.TimeoutException: Idle timeout expired: 10001/10000 ms
2017-12-28 11:05:38.299:DBUG:oejuc.AbstractLifeCycle:main: stopping org.eclipse.jetty.server.Server@4b1210ee[9.4.z-SNAPSHOT]

@sbordet thoughts?

[gregw]

Can that - the callback does get called, but just closes the connection. But an IOException should still be returned to the application???

[gregw]

The problem is that this test request sends absolutely no content and the HttpConfiguration is in the default delayDispatchUntilContent mode. So the request is not even dispatched to the application yet, so it has not even started reading, thus no chance to throw an IOException.

If I added the following line while setting up the server:

        jetty.getBean(ServerConnector.class).getConnectionFactory(HttpConnectionFactory.class).getHttpConfiguration().setDelayDispatchUntilContent(false);

the test works as expected.

So we have to consider what is the correct handling of an IdleTimeout when in DelayDispatchUntilContent mode. Currently we treat it exactly as a timeout within the headers, so it is as if the request never actually arrived. This might be a little bit wrong, but it might be a reasonable price to pay for this optimization mode.

I'll review the code and see if there is an opportunity for the request to be dispatched with the HttpInput already in a timeout failed state.... @sbordet thoughts?

[sbordet]

The delayDispatchUntilContent feature is there in 9.2.x, but it defaulted to false, while in 9.4.x defaults to true.

@gregw I think it would be strange for a request to be dispatched after the idle timeout with an already failed HttpInput; consider those that have timing filters that will see a request and an immediate TimeoutException saying "idle timeout" when the request was actually dispatched few microseconds before.
However, I don't see a better alternative; perhaps the exception could be very detailed (or perhaps even a subclass of TimeoutException) in explaining that is a "special" dispatch for idle timed out requests.

[sbordet]

@gregw, we already have a test case that tests idle timeout with delayDispatchUntilContent, namely ServerTimeoutsTest.testDelayedDispatchRequestWithDelayedFirstContentIdleTimeoutFires().
Currently that test only tests for delayDispatchUntilContent=true, we should expand it for delayDispatchUntilContent=false so that it tests for all transports.

So that test really encodes the fact that the Handler is not called.

Also @gregw, I don't think commit 0706e53 is right, as it only addresses HTTP/1.1.
Plus, onReadTimeout() is there only for backwards compatibility, as the preferred mechanism is now Connection.onIdleExpired().
If there is a mechanism to dispatch with a failed HttpInput, then preferably should be the same for all transports.

[sbordet]

@gregw, we need to discuss whether it's okay to call the application with a failed HttpInput.

One can see such requests as an attack and deem them not viable to be dispatched to the application (thus consuming a thread, and possibly have other side effects such as calling a third party service, starting to write the response, etc.)
For example, would a proxy like to see these requests ? The proxy would setup a lot of machinery to forward to the server, only to fail immediately when it starts reading the request content.

So yes it's a behavioral change from 9.2.x, but I'm slightly inclined to think it's a better behavior although I recon there are pros in dispatching too (for example, RequestLog tracking).

I would close and discard #2083 until we have decided what is the right behavior.

[gregw]

@sbordet I think it is strange for an optimisation to change the outcome. Without delayed dispatch a request sent without its body will invoke the application and be logged as a request. With delayed dispatch such a request not logged and does not invoke the application. I don't see this as anymore of an attack then sending 1 byte of the content and then pausing.

So I think the behaviour is right.

However #2083 is just my initial attempt to see how difficult it may be. As I said, it doesn't consider the other transports. So if there is a better place to implement it that is not transport specific, then I'm definitely happy to redo.

Perhaps an alternate solution should be to only delay dispatch for a short period of time - perhaps even user configurable? But I'm not really keen on adding more timers - even cyclic ones.

[gregw]

I don't understand your comments about onReadTimeout being replaced with onIdleExpired?

They are different methods with different semantics. onIdleExpired is a check to ensure the endpoint really is idle - it's the last chance to say there was some action. onReadTimeout is a notification that a read was outstanding when we went idle and it returns false (don't close) if the application has handled it.

Anyway, I don't think this is a high priority, so let's wait until we can hangout before discussing further... unless one of us has an idea about how/where to do this that is common to all transports

[sbordet]

@gregw I agree that we should dispatch with an already failed HttpInput and that the value of HttpConfiguration.delayDispatchUntilContent should not impact the behavior.

[hchengqiang]

how to edit the test case and this exception thrown in HttpOutput??
java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 30001/30000 ms
at org.eclipse.jetty.util.SharedBlockingCallback$Blocker.block(SharedBlockingCallback.java:226) ~[jetty-util-9.3.0.v20150612.jar:9.3.9.v20160517]
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:164) ~[jetty-server-9.3.0.v20150612.jar:9.3.9.v20160517]
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:530) ~[jetty-server-9.3.0.v20150612.jar:9.3.9.v20160517]

[sbordet]

@hchengqiang please open a new issue and detail exactly what's your problem.

Why you want to "edit test case"?

Explain in the new issue what you are doing, what's the exact Jetty version and configuration, what do you expect and what happens instead.