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

Handle request replays by Jetty due to timeout of long-running async request #448

Open
pikob opened this Issue Dec 5, 2018 · 10 comments

Comments

Projects
None yet
2 participants
@pikob
Copy link

pikob commented Dec 5, 2018

I've encountered an issue with async execution of long-running jobs.

If a back-end service takes longer than 30 seconds to process an asynchronous request, Jetty will replay the request, while setting response code to 500. Javalin will also replay the request as it would a normal request, except that body is this time empty. I wrote a short demo that shows how Javalin handles it. See log output below for details on what goes on. This SO question also mentions it.

(Btw, 30 second timeout is a property defined in org.eclipse.jetty.HttpChannelState.DEFAULT_TIMER and can be set via. system property which is pretty awkward. I haven't found another way to set it.)

Here's example code that triggers the timeout (using io.restassured to issue a request):

long asyncTimeout = Long.getLong("org.eclipse.jetty.server.HttpChannelState.DEFAULT_TIMEOUT", 30000);
CompletableFuture<Object> future = new CompletableFuture<>();

Javalin j = Javalin.create();

j.before(ctx -> {
  // cannot access async context here yet
  System.out.println(Instant.now() + " BEFORE disp=" +
    ctx.req.getDispatcherType() + " " + ctx.req.getRequestURI() +
    " " + " body='" + ctx.body() + "' " + ctx.status());
});
j.after(ctx -> {
  System.out.println(Instant.now() + " " + "AFTER uri='" +
    ctx.req.getRequestURI() + "' " + " body='" + ctx.body() + "' " +
    ctx.status() + " result='" + ctx.resultString() + "'");
});

j.get("/async", ctx -> ctx.result(future));

j.start();

Executors.newSingleThreadScheduledExecutor().schedule(() -> future.complete("result"), asyncTimeout + 5000, TimeUnit.MILLISECONDS);

given().port(j.port()).body("{\"param\":\"data\"}").get("/async").then().log().all();

and here is the output, with wire data logged in restassured:

2590  [main] DEBUG wire       -  >> "GET /async HTTP/1.1[\r][\n]" 
2591  [main] DEBUG wire       -  >> "Accept: */*[\r][\n]" 
2591  [main] DEBUG wire       -  >> "Content-Type: text/plain; charset=ISO-8859-1[\r][\n]" 
2591  [main] DEBUG wire       -  >> "Content-Length: 16[\r][\n]" 
2591  [main] DEBUG wire       -  >> "Host: localhost:7000[\r][\n]" 
2591  [main] DEBUG wire       -  >> "Connection: Keep-Alive[\r][\n]" 
2591  [main] DEBUG wire       -  >> "User-Agent: Apache-HttpClient/4.5.3 (Java/1.8.0_112)[\r][\n]" 
2591  [main] DEBUG wire       -  >> "Accept-Encoding: gzip,deflate[\r][\n]" 
2591  [main] DEBUG wire       -  >> "[\r][\n]" 
2591  [main] DEBUG wire       -  >> "{"param":"data"}" 
2018-12-04T20:08:35.365Z BEFORE disp=REQUEST /async  body='{"param":"data"}' 200
2018-12-04T20:09:05.374Z BEFORE disp=ERROR /async  body='' 500
2018-12-04T20:09:08.967Z AFTER uri='/async'  body='' 500 result='result'
36265 [main] DEBUG wire       -  << "HTTP/1.1 500 Server Error[\r][\n]" 
36267 [main] DEBUG wire       -  << "Server: Javalin[\r][\n]" 
36267 [main] DEBUG wire       -  << "Content-Type: text/plain[\r][\n]" 
36267 [main] DEBUG wire       -  << "Content-Length: 6[\r][\n]" 
36267 [main] DEBUG wire       -  << "[\r][\n]" 
2018-12-04T20:09:08.977Z AFTER uri='null'  body='{"param":"data"}' 200 result='result'
36351 [main] DEBUG wire       -  << "result" 
HTTP/1.1 500 Server Error
Server: Javalin
Content-Type: text/plain
Content-Length: 6

result

I haven't found an explicit way to handle such timeout within Javalin. I don't really have an opinion on how to improve it due to lack of experience with web servers (highlighted by the fact that I ran into this issue at all by designing a 'REST' service that regularly takes 30+ seconds to respond). Sorry :)

My workaround was to tack a continuation to this task that sets status code to 200. Then I save the task into session attribute on first request and use it on followup requests to re-set Javalin's ctx.result(CompletableFuture<?>). That messes up request timing, but otherwise seems to work. When the future finishes, I see after handlers being triggered for each request, but only the last one returns to client. I also had to put some code into AccessManager to skip re-authorizing these repeated requests.

@tipsy tipsy added the QUESTION label Dec 5, 2018

@tipsy

This comment has been minimized.

Copy link
Owner

tipsy commented Dec 5, 2018

Thanks for the thorough issue, but it's still bit unclear to me what your question/feature request is. Do you a way to configure what should happen for timeouts?

@pikob

This comment has been minimized.

Copy link

pikob commented Dec 7, 2018

Sorry for not being more clear. I initially just wanted to point out a sore spot I encountered using Javalin and to outline a rough solution.

After some thought I think adding asyncTimeout configuration to Javalin would do the trick. It just needs to set the timeout on AsyncContext when it gets created in JavalinServlet.kt.

Somehow exposing AsyncContext (created in JavalinServlet.kt) or providing interface to add AsyncListener to it would also be interesting, but it feels a bit low-level for Javalin, and more convoluted.

@tipsy

This comment has been minimized.

Copy link
Owner

tipsy commented Dec 12, 2018

@pikob Would your problem be solved by just increasing the timeout? You should be able to adjust it by configuring a custom connector:

Server(QueuedThreadPool(200, 8, 120_000)).apply {
    connectors = arrayOf(ServerConnector(server).apply {
        port = 1234
        idleTimeout = 120_000
    })
}

I'm not sure about letting users configure async. As you say, it's a bit low-level for Javalin. You can always call ctx.req.startAsync() and take care of everything yourself, the async functionality offered by Javalin is supposed to cover the simplest and most common use cases.

@pikob

This comment has been minimized.

Copy link

pikob commented Dec 13, 2018

Sorry, that doesn't look like the same timeout to me. Async timeout times out requests that don't get a response within 30s. In which case, Jetty 'replays' the original request with some modifications (notably, body is empty). I understand it as a way of handling non-responsive back-end services.

If there was a convenient way to set it, in a manner you proposed, yes, it would be a partial solution. Setting the async timeout to 0 actually leaves async requests waiting indefinitely (see line 900 of HttpChannelState). But async timeout is sourced from a final static variable from system property (can't set it in code), or set in AsyncContext.

I'm not sure about letting users configure async. As you say, it's a bit low-level for Javalin. You can always call ctx.req.startAsync() and take care of everything yourself, the async functionality offered by Javalin is supposed to cover the simplest and most common use cases.

Sure. Ideally, Javalin would offer a simple way to explicitly handle unresponsive back-end, but it is how it is. I'm toying with the idea of creating a PR, unfortunately time is scarce. It might be a good idea to document given behavior though - unaware user (like me) will be faced with this as soon as some back-end task takes longer than 30s (talking to another micro-service that times out, for example), and it will likely break things depending on how requests are structured.

@tipsy

This comment has been minimized.

Copy link
Owner

tipsy commented Dec 13, 2018

@pikob you're right, I didn't really research this properly before replying (sorry about that). I see that ring had the same issue (ring-clojure/ring@3e24fbd), and they chose to set it to 0 by default.

I'm toying with the idea of creating a PR, unfortunately time is scarce.

That would be very much appreciated. Even if no other Javalin users have reported this, it seems to be a pretty common problem with Jetty.

It might be a good idea to document given behavior though - unaware user (like me) will be faced with this as soon as some back-end task takes longer than 30s (talking to another micro-service that times out, for example), and it will likely break things depending on how requests are structured.

I'll try to get it done in the next few days.

@tipsy

This comment has been minimized.

Copy link
Owner

tipsy commented Dec 16, 2018

@tipsy

This comment has been minimized.

Copy link
Owner

tipsy commented Jan 12, 2019

@pikob I was trying to solve an unrelated issue, and I used an after-filter to modify the timeout:

app.after(ctx -> ctx.req.getAsyncContext().setTimeout(10));
@pikob

This comment has been minimized.

Copy link

pikob commented Jan 12, 2019

@tipsy I find this suspicious. Did that line really have an effect? For me, after filter fires after request job is completed and just before replying to client. It's too late to set the timer then. See lines 115-127 in JavalinServlet.kt.

I am guessing the timer can onky be set just after startAsync() call, but haven't actually tried it with raw Jetty.

@tipsy

This comment has been minimized.

Copy link
Owner

tipsy commented Jan 12, 2019

Yes, but I guess it was somewhat of a special case. I used it to close a SSE connection in a test: #273

I agree that it shouldn't work in your case, I'm a bit too quick to share.

I can add a param for configuring this in JavalinServlet though, seems pretty straightforward.

Edit: they should really move the close button on mobile.

@tipsy

This comment has been minimized.

Copy link
Owner

tipsy commented Jan 14, 2019

@pikob added an option to configure it per request in #465

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment