Request timeout is resulting

[dlvenable]

We are seeing issues where a request timeout in our Armeria server is resulting in a 503 Service Unavailable status. I have experimented with this and found a way to reproduce with cURL. But, when I try to handle this error, I still get the 503 Service Unavailable response.

I created a web server to attempt to reproduce this. You can see it all in isolation here:

https://github.com/dlvenable/armeria-sample/blob/9564375620b329fcfd254a25efe8bdfc9e58480c/src/main/java/io/venable/samples/armeria/request_timeout/RequestTimeoutExperiment.java

I then run:

curl -v http://localhost:8080/test -X POST -H 'Content-Type: application/json' -H 'Content-Length: 100'

It results in:

*   Trying [::1]:8080...
* Connected to localhost (::1) port 8080
> POST /test HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/8.4.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 100
>
< HTTP/1.1 503 Service Unavailable
< content-type: text/plain; charset=utf-8
< content-length: 45
< server: Armeria/1.27.3
< date: Fri, 5 Apr 2024 18:58:06 GMT
<
Status: 503
Description: Service Unavailable
* Connection #0 to host localhost left intact

I see the following logs:

[armeria-common-worker-kqueue-3-1] INFO io.venable.samples.armeria.request_timeout.RequestTimeoutExperiment - In decorator
[armeria-common-worker-kqueue-3-1] ERROR io.venable.samples.armeria.request_timeout.RequestTimeoutExperiment - Error in decorator
com.linecorp.armeria.common.ResponseCompleteException
[armeria-common-worker-kqueue-3-2] WARN com.linecorp.armeria.server.DefaultUnhandledExceptionsReporter - Observed 1 exception(s) that didn't reach a LoggingService in the last 10000ms(10000000000ns). Please consider adding a LoggingService as the outermost decorator to get detailed error logs. One of the thrown exceptions:
com.linecorp.armeria.server.RequestTimeoutException
	at com.linecorp.armeria.server.RequestTimeoutException.get(RequestTimeoutException.java:36)
	at com.linecorp.armeria.internal.common.DefaultCancellationScheduler.invokeTask(DefaultCancellationScheduler.java:512)
	at com.linecorp.armeria.internal.common.DefaultCancellationScheduler.lambda$start$2(DefaultCancellationScheduler.java:148)

From this experiment I see that the specific exception which is passed into the decorator is ResponseCompleteException.

However, even though I return a HttpStatus.REQUEST_TIMEOUT response, I get the same 513 error.

https://github.com/dlvenable/armeria-sample/blob/9564375620b329fcfd254a25efe8bdfc9e58480c/src/main/java/io/venable/samples/armeria/request_timeout/RequestTimeoutExperiment.java#L76-L79

It appears that there may be a bug here. Otherwise, am I configuring something incorrectly here?

[minwoox]

Because you didn't send the body, the request isn't aggregated:
https://github.com/dlvenable/armeria-sample/blob/9564375620b329fcfd254a25efe8bdfc9e58480c/src/main/java/io/venable/samples/armeria/request_timeout/RequestTimeoutExperiment.java#L74

After 5 seconds, the request is timed out and 503 is sent to the client.

armeria/core/src/main/java/com/linecorp/armeria/server/DefaultServerErrorHandler.java

Lines 89 to 92 in 5f6a3b4

	if (cause instanceof RequestTimeoutException) {
	return internalRenderStatus(serviceConfig, ctx.request().headers(),
	HttpStatus.SERVICE_UNAVAILABLE, cause);
	}

Because the response is sent to the server, the request is exceptionally complete with ResponseCompleteException.

armeria/core/src/main/java/com/linecorp/armeria/server/HttpServerHandler.java

Lines 740 to 746 in 0ab1721

	private void handleResponseComplete(@Nullable Throwable cause) {
	if (cause == null || !req.isOpen()) {
	req.abort(ResponseCompleteException.get());
	} else {
	req.abort(cause);
	}
	handleRequestOrResponseComplete();

Eventually, the request is exceptionally complete with the ResponseCompleteException.
https://github.com/dlvenable/armeria-sample/blob/9564375620b329fcfd254a25efe8bdfc9e58480c/src/main/java/io/venable/samples/armeria/request_timeout/RequestTimeoutExperiment.java#L74

Even though you try to send the HttpStatus.REQUEST_TIMEOUT, it's not sent to the client because the response is already sent.
https://github.com/dlvenable/armeria-sample/blob/9564375620b329fcfd254a25efe8bdfc9e58480c/src/main/java/io/venable/samples/armeria/request_timeout/RequestTimeoutExperiment.java#L78

If you wish to return HttpStatus.REQUEST_TIMEOUT, you can do that by setting a ServerErrorHandler:

armeria/core/src/main/java/com/linecorp/armeria/server/ServerBuilder.java

Line 1730 in a54f418

public ServerBuilder errorHandler(ServerErrorHandler errorHandler) {

By the way, I think we need to fix Armeria server return HttpStatus.REQUEST_TIMEOUT if it doesn't receive the request fully.

The 408 (Request Timeout) status code indicates that the server did not receive a complete request message within the time that it was prepared to wait.

If the client has an outstanding request in transit, it MAY repeat that request. If the current connection is not usable (e.g., as it would be in HTTP/1.1 because request delimitation is lost), a new connection will be used.

https://httpwg.org/specs/rfc9110.html#status.408

Let me create an issue for that.

[dlvenable]

@minwoox , Thank you for the detailed response. This helps a lot, and now I understand why the exception was not brought into the Decorator.

I tried the solution you suggested to use the errorHandler and it worked as you suggested.

However, we do use an annotatedService. And I get different results when switching to an annotatedService.

You can see these three lines here: https://github.com/dlvenable/armeria-sample/blob/c49e968fff07b49a2ab2212e70984d60b408a44e/src/main/java/io/venable/samples/armeria/request_timeout/RequestTimeoutExperiment.java#L51-L53

When I use .service("/test", (ctx, req) -> HttpResponse.of("Hello, Armeria!")) with the errorHandler I get the 408 I'm looking for. But, when I switch to use .annotatedService("/test", new MyService()), I get an empty response from the server. This is also interesting because the previous response was a 503, but now I get no response.

Also, I did trying adding it to the ExceptionHandlerFunction, but this had not affect. I think this is intended to handle exceptions from my service code, so that isn't too surprising.

What do you think the solution is here?

By the way, I think we need to fix Armeria server return HttpStatus.REQUEST_TIMEOUT if it doesn't receive the request fully.

I agree that this is the best long-term solution. This should be the default response for this situation.

[dlvenable]

Here is the behavior from the annotatedService:

curl -v http://localhost:8080/test -X POST -H 'Content-Type: application/json' -H 'Content-Length: 100'

output:

*   Trying [::1]:8080...
* Connected to localhost (::1) port 8080
> POST /test HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/8.4.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 100
>
* Empty reply from server
* Closing connection
curl: (52) Empty reply from server

[minwoox]

Oops, we have a bug.
We wait for the request to be aggregated in the decoder:

armeria/core/src/main/java/com/linecorp/armeria/server/Http1RequestDecoder.java

Line 277 in 6e485eb

if (!req.needsAggregation()) {

So the service request context isn't created which triggers the timeout exception. 😓
Let me fix that soon. Thanks for the report!

[dlvenable]

@minwoox , When do you think you could have a fix for the decoder? This is something that is causing us some significant difficulties.

[minwoox]

@dlvenable, Will release the patch version next week. Thanks a lot for your patience.

[minwoox]

@dlvenable, it's fixed in https://armeria.dev/release-notes/1.28.2. 😆

[dlvenable]

Thank you @minwoox for making this fix and releasing the patch!