Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Async requests are not considered when shutting down gracefully #2717

Closed
wilkinsona opened this issue Jul 13, 2018 · 5 comments
Closed

Async requests are not considered when shutting down gracefully #2717

wilkinsona opened this issue Jul 13, 2018 · 5 comments

Comments

@wilkinsona
Copy link
Contributor

wilkinsona commented Jul 13, 2018

I'm trying to enhance Spring Boot's Jetty integration to optionally gracefully shut down Jetty. It's working nicely for synchronous requests but does not work for asynchronous requests. If I call StatisticsHandler.shutdown when there's a single asynchronous request in progress, the returned future is completed immediately rather than only completing once the request has completed.

Here's the stats HTML captured at the time of StatisticsHandler calling shutdown.succeeded():

<h1>Statistics:</h1>
Statistics gathering started 14026ms ago<br />
<h2>Requests:</h2>
Total requests: 1<br />
Active requests: 1<br />
Max active requests: 1<br />
Total requests time: 0<br />
Mean request time: 0.0<br />
Max request time: 0<br />
Request time standard deviation: 0.0<br />
<h2>Dispatches:</h2>
Total dispatched: 1<br />
Active dispatched: 0<br />
Max active dispatched: 1<br />
Total dispatched time: 32<br />
Mean dispatched time: 32.0<br />
Max dispatched time: 32<br />
Dispatched time standard deviation: 0.0<br />
Total requests suspended: 1<br />
Total requests expired: 0<br />
Total requests resumed: 0<br />
<h2>Responses:</h2>
1xx responses: 0<br />
2xx responses: 0<br />
3xx responses: 0<br />
4xx responses: 0<br />
5xx responses: 0<br />
Bytes sent total: 0<br />
@joakime
Copy link
Contributor

joakime commented Jul 13, 2018

Interesting. Do you have a testcase or demo project demonstrating this we can use?

@wilkinsona
Copy link
Contributor Author

This should reproduce the behaviour that I've described with 9.4.11:

package com.example;

import java.io.IOException;
import java.util.concurrent.CountDownLatch;

import javax.servlet.AsyncContext;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import org.eclipse.jetty.server.Server;
import org.eclipse.jetty.server.handler.StatisticsHandler;
import org.eclipse.jetty.servlet.ServletContextHandler;

public class JettyGracefulShutdown {

	private static CountDownLatch latch = new CountDownLatch(1);

	public static void main(String[] args) throws Exception {
		Server server = new Server(8080);
		server.setStopTimeout(30000);
		ServletContextHandler contextHandler = new ServletContextHandler();
		contextHandler.setContextPath("/");
		contextHandler.addServlet(AsyncServlet.class, "/async").setAsyncSupported(true);
		contextHandler.addServlet(SyncServlet.class, "/sync").setAsyncSupported(true);
		server.setHandler(contextHandler);
		StatisticsHandler handler = new StatisticsHandler();
		handler.setHandler(server.getHandler());
		server.setHandler(handler);
		server.start();
		System.out.println("Waiting for a request to /sync or /async");
		latch.await();
		System.out.println("Request received. Shutting down");
		long start = System.currentTimeMillis();
		server.stop();
		long duration = System.currentTimeMillis() - start;
		System.out.println("Shutdown complete in " + duration + "ms");
	}

	public static class AsyncServlet extends HttpServlet {

		@Override
		protected void doGet(HttpServletRequest req, HttpServletResponse resp)
				throws ServletException, IOException {
			AsyncContext context = req.startAsync();
			context.start(() -> {
				latch.countDown();
				try {
					Thread.sleep(10000);
				}
				catch (InterruptedException ex) {
					Thread.currentThread().interrupt();
				}
				context.complete();
			});
		}

	}

	public static class SyncServlet extends HttpServlet {

		@Override
		protected void doGet(HttpServletRequest req, HttpServletResponse resp)
				throws ServletException, IOException {
			latch.countDown();
			try {
				Thread.sleep(10000);
			}
			catch (InterruptedException ex) {
				Thread.currentThread().interrupt();
			}
		}

	}

}

Start the server and then make a request to /sync:

$ time curl -i localhost:8080/sync
HTTP/1.1 200 OK
Date: Fri, 13 Jul 2018 14:22:07 GMT
Transfer-Encoding: chunked
Server: Jetty(9.4.11.v20180605)


real	0m10.121s
user	0m0.007s
sys	0m0.005s

It takes just over 10 seconds as expected.

Start the server again and make a request to /async:

$ time curl -i localhost:8080/async
curl: (52) Empty reply from server

real	0m0.113s
user	0m0.007s
sys	0m0.004s

The connection's dropped, resulting in an empty reply almost immediately. Note that the shutdown still takes just over 10 seconds to complete so something's waiting for the request to complete. When it does complete It tries to send the response but it fails because the connection's already been dropped:

15:22:51.725 [qtp2030562336-16] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - ran ReservedThreadExecutor@146ba0ac{s=0/8,p=0}@466125ce
15:23:01.710 [qtp2030562336-15] DEBUG org.eclipse.jetty.server.HttpChannelState - complete HttpChannelState@de0d827{s=ASYNC_WAIT a=STARTED i=false r=IDLE w=false}
15:23:01.711 [qtp2030562336-15] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@4a8516a9{r=1,c=false,a=ASYNC_WOKEN,uri=//localhost:8080/async,age=10016} handle //localhost:8080/async 
15:23:01.711 [qtp2030562336-15] DEBUG org.eclipse.jetty.server.HttpChannelState - handling HttpChannelState@de0d827{s=ASYNC_WOKEN a=COMPLETE i=false r=IDLE w=false}
15:23:01.711 [qtp2030562336-15] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@4a8516a9{r=1,c=false,a=COMPLETING,uri=//localhost:8080/async,age=10016} action COMPLETE
15:23:01.712 [qtp2030562336-15] DEBUG org.eclipse.jetty.server.HttpChannel - sendResponse info=null content=HeapByteBuffer@32f70bd7[p=0,l=0,c=0,r=0]={<<<>>>} complete=true committing=true callback=Blocker@28046122{null}
15:23:01.712 [qtp2030562336-15] DEBUG org.eclipse.jetty.server.HttpChannel - COMMIT for /async on HttpChannelOverHttp@4a8516a9{r=1,c=true,a=COMPLETING,uri=//localhost:8080/async,age=10017}
200 null HTTP/1.1
Date: Fri, 13 Jul 2018 14:22:51 GMT


15:23:01.714 [qtp2030562336-15] DEBUG org.eclipse.jetty.server.HttpChannel - Commit failed
org.eclipse.jetty.io.EofException: null
	at org.eclipse.jetty.server.HttpConnection$SendCallback.reset(HttpConnection.java:714)
	at org.eclipse.jetty.server.HttpConnection$SendCallback.access$300(HttpConnection.java:678)
	at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:536)
	at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:790)
	at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:846)
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:240)
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:216)
	at org.eclipse.jetty.server.HttpOutput.close(HttpOutput.java:298)
	at org.eclipse.jetty.server.Response.closeOutput(Response.java:1048)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:493)
	at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:293)
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1390)
	at org.eclipse.jetty.server.HttpChannelState.runInContext(HttpChannelState.java:1113)
	at org.eclipse.jetty.server.HttpChannelState.complete(HttpChannelState.java:697)
	at org.eclipse.jetty.server.AsyncContextState.complete(AsyncContextState.java:99)
	at com.example.JettyGracefulShutdown$AsyncServlet.lambda$0(JettyGracefulShutdown.java:55)
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1408)
	at org.eclipse.jetty.server.AsyncContextState$2.run(AsyncContextState.java:176)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680)
	at java.lang.Thread.run(Thread.java:748)

@sbordet
Copy link
Contributor

sbordet commented Jul 13, 2018

Uhm. Don't you have a CountDownLatch with count=1, but make 2 requests?

What happens if you first try /async and then /sync?

@wilkinsona
Copy link
Contributor Author

I guess you haven't tried running the example. Calling /sync causes the JVM to exit after the request has completed. That why I said "Start the server again and make a request to /async" in the instructions above.

@sbordet
Copy link
Contributor

sbordet commented Jul 13, 2018

Now I ran the example 😃

To discuss your original intent, shutting down gracefully a server that may be bombed with requests is kind of hard, but here's what I suggest:

  1. Call ServerConnector.setAccepting(false). This will stop Jetty from accepting new connections.

  2. Now you need a way to cancel new requests arriving in existing connections.
    This can be done in a custom handler that is the first to be hit and that somehow can be notified when it needs to start rejecting requests.

  3. Then you need to wait for existing requests to finish.
    Jetty's Server class inherits a stopTimeout that can be set to a desired value (by default 30 s).
    Stopping the Server will tap into the shutdown() method which will return a future that Jetty will wait on.

Unfortunately, StatisticsHandler waits until _dispatchedStats.getCurrent() == 0 but that is not correct, it should have waited on _requestStats.getCurrent() == 0. @gregw your thoughts here?
If I modify StatisticsHandler to wait on _requestStats @wilkinsona's case will work fine.

@wilkinsona if you don't have 2. then it may be that getCurrent() never goes to zero, and eventually the stopTimeout will elapse and forcibly close connections - so it's really your call if you want to implement 2. for a more graceful shutdown, or if the existing mechanism (without 2.) is enough for you.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants