Uploading large files will cause unexpected timeouts

Blaze サーバーの responseHeaderTimeout 設定から始め、ドキュメントに記載された動作を curl による再現およびサーバーログと比較します。大容量のアップロードが 30 秒後に 503 を受け取る理由を特定し、その後、アップロードが早すぎるタイムアウトなしに完了することを確認します。

Verison

val http4sBlaze = "0.23.12"
val http4s = "0.23.13"

val http4s = Seq(
    "org.http4s" %% "http4s-blaze-server" % http4sBlaze,
    "org.http4s" %% "http4s-blaze-client" % http4sBlaze,
    "org.http4s" %% "http4s-core"         % http4s,
    "org.http4s" %% "http4s-circe"        % http4s
  )

Problem

I'm using http4s to provoid a server which user can upload file to S3 bucket.

I generate a file and try to upload it.

$ dd if=/dev/zero of=/tmp/test bs=1M count=2000

$ time curl  -vvvv --location --request PUT 'http://localhost:9000/upload' --header 'Content-Type: application/octet-stream' -T '/tmp/test'

*   Trying 127.0.0.1:9000...
* Connected to localhost (127.0.0.1) port 9000 (#0)
> PUT /upload
> Host: localhost:9000
> User-Agent: curl/7.79.1
> Accept: */*
> Content-Type: application/octet-stream
> Content-Length: 314572800
> Expect: 100-continue
> 
* Done waiting for 100-continue
* Mark bundle as not supporting multiuse
< HTTP/1.1 503 Service Unavailable
< Content-Type: text/plain; charset=UTF-8
< Date: Thu, 30 Jun 2022 04:05:37 GMT
< Content-Length: 18
* HTTP error before end of send, stop sending
< 
* Closing connection 0
Response timed outcurl -vvvv --location --request PUT  --header  -T '/tmp/test'  0.02s user 0.11s system 0% cpu 30.601 total

After 30 seconds, it return http code 503, meanwhile, the server log shows as following

|0000ffe0| 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
|0000fff0| 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
+--------+-------------------------------------------------+----------------+
12:05:37.440 [aws-java-sdk-NettyEventLoop-1-4] DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xaa7fac0c, L:/192.168.1.118:49744 - R:warehorse.s3.cn-northwest-1.amazonaws.com.cn/52.82.189.44:443] FLUSH
12:05:37.593 [aws-java-sdk-NettyEventLoop-1-4] DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xaa7fac0c, L:/192.168.1.118:49744 - R:warehorse.s3.cn-northwest-1.amazonaws.com.cn/52.82.189.44:443] EXCEPTION: java.io.IOException: Request cancelled
java.io.IOException: Request cancelled
	at software.amazon.awssdk.http.nio.netty.internal.FutureCancelHandler.exceptionCaught(FutureCancelHandler.java:43)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273)
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireExceptionCaught(CombinedChannelDuplexHandler.java:424)
	at io.netty.channel.ChannelHandlerAdapter.exceptionCaught(ChannelHandlerAdapter.java:92)
	at io.netty.channel.CombinedChannelDuplexHandler$1.fireExceptionCaught(CombinedChannelDuplexHandler.java:145)
	at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:143)
	at io.netty.channel.CombinedChannelDuplexHandler.exceptionCaught(CombinedChannelDuplexHandler.java:231)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273)
	at io.netty.handler.ssl.SslHandler.exceptionCaught(SslHandler.java:1122)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.exceptionCaught(DefaultChannelPipeline.java:1377)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.DefaultChannelPipeline.fireExceptionCaught(DefaultChannelPipeline.java:907)
	at software.amazon.awssdk.http.nio.netty.internal.NettyRequestExecutor.lambda$null$1(NettyRequestExecutor.java:125)
	at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
	at io.netty.util.concurrent.PromiseTask.run(PromiseTask.java:106)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at java.base/java.lang.Thread.run(Thread.java:833)
12:05:37.599 [zio-default-async-46] DEBUG org.http4s.blaze.server.Http1ServerStage$$anon$1 - Websocket key: None
Request headers: Headers(Host: localhost:9000, User-Agent: curl/7.79.1, Accept: */*, Content-Type: application/octet-stream, Content-Length: 314572800, Expect: 100-continue)
12:05:37.706 [aws-java-sdk-NettyEventLoop-1-4] DEBUG software.amazon.awssdk.http.nio.netty.internal.ResponseHandler - Exception processing request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=warehorse.s3.cn-northwest-1.amazonaws.com.cn, port=443, encodedPath=/counter-large-file-1, headers=[amz-sdk-invocation-id, amz-sdk-request, Authorization, Content-Length, Content-Type, Expect, Host, User-Agent, x-amz-acl, x-amz-content-sha256, X-Amz-Date, x-amz-meta-Accept, x-amz-meta-Content-Length, x-amz-meta-Content-Type, x-amz-meta-Expect, x-amz-meta-Host, x-amz-meta-User-Agent], queryParameters=[])
java.io.IOException: Request cancelled
	at software.amazon.awssdk.http.nio.netty.internal.FutureCancelHandler.exceptionCaught(FutureCancelHandler.java:43)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273)
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireExceptionCaught(CombinedChannelDuplexHandler.java:424)
	at io.netty.channel.ChannelHandlerAdapter.exceptionCaught(ChannelHandlerAdapter.java:92)
	at io.netty.channel.CombinedChannelDuplexHandler$1.fireExceptionCaught(CombinedChannelDuplexHandler.java:145)
	at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:143)
	at io.netty.channel.CombinedChannelDuplexHandler.exceptionCaught(CombinedChannelDuplexHandler.java:231)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273)
	at io.netty.handler.ssl.SslHandler.exceptionCaught(SslHandler.java:1122)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.exceptionCaught(DefaultChannelPipeline.java:1377)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.DefaultChannelPipeline.fireExceptionCaught(DefaultChannelPipeline.java:907)
	at software.amazon.awssdk.http.nio.netty.internal.NettyRequestExecutor.lambda$null$1(NettyRequestExecutor.java:125)
	at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
	at io.netty.util.concurrent.PromiseTask.run(PromiseTask.java:106)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at java.base/java.lang.Thread.run(Thread.java:833)
12:05:37.708 [aws-java-sdk-NettyEventLoop-1-4] DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xaa7fac0c, L:/192.168.1.118:49744 - R:warehorse.s3.cn-northwest-1.amazonaws.com.cn/52.82.189.44:443] CLOSE
12:05:37.729 [zio-default-async-36] INFO org.http4s.blaze.server.Http1ServerStage$$anon$1 - HTTP body not read to completion. Dropping connection.
12:05:37.729 [zio-default-async-36] DEBUG org.http4s.blaze.server.Http1ServerStage$$anon$1 - closeConnection()
12:05:37.729 [zio-default-async-36] DEBUG org.http4s.blaze.server.Http1ServerStage$$anon$1 - Shutting down HttpPipeline
12:05:37.730 [zio-default-async-36] DEBUG org.http4s.blaze.server.Http1ServerStage$$anon$1 - Shutting down.
12:05:37.730 [zio-default-async-36] DEBUG org.http4s.blaze.server.Http1ServerStage$$anon$1 - Shutting down HttpPipeline
12:05:37.730 [zio-default-async-36] DEBUG org.http4s.blaze.server.Http1ServerStage$$anon$1 - Shutting down.
12:05:37.730 [zio-default-async-36] DEBUG org.http4s.blazecore.IdleTimeoutStage - Shutting down idle timeout stage
12:05:37.730 [zio-default-async-36] DEBUG org.http4s.blazecore.IdleTimeoutStage - Shutting down.
12:05:37.730 [zio-default-async-36] DEBUG org.http4s.blaze.channel.nio1.NIO1HeadStage - Shutting down.
12:05:37.731 [blaze-selector-0] DEBUG org.http4s.blaze.channel.nio1.NIO1HeadStage - Stage NIO1HeadStage sending inbound command: Disconnected
12:05:37.731 [blaze-selector-0] DEBUG org.http4s.blazecore.IdleTimeoutStage - Shutting down idle timeout stage
12:05:37.731 [blaze-selector-0] DEBUG org.http4s.blazecore.IdleTimeoutStage - Shutting down.
12:05:37.731 [blaze-selector-0] DEBUG org.http4s.blazecore.IdleTimeoutStage - Stage IdleTimeoutStage sending inbound command: Disconnected
12:05:37.731 [blaze-selector-0] DEBUG org.http4s.blaze.server.Http1ServerStage$$anon$1 - Shutting down HttpPipeline
12:05:37.731 [blaze-selector-0] DEBUG org.http4s.blaze.server.Http1ServerStage$$anon$1 - Shutting down.
12:05:37.852 [aws-java-sdk-NettyEventLoop-1-4] DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xaa7fac0c, L:/192.168.1.118:49744 - R:warehorse.s3.cn-northwest-1.amazonaws.com.cn/52.82.189.44:443] WRITABILITY CHANGED
12:05:37.854 [aws-java-sdk-NettyEventLoop-1-4] DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xaa7fac0c, L:/192.168.1.118:49744 ! R:warehorse.s3.cn-northwest-1.amazonaws.com.cn/52.82.189.44:443] INACTIVE
12:05:37.854 [aws-java-sdk-NettyEventLoop-1-4] DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xaa7fac0c, L:/192.168.1.118:49744 ! R:warehorse.s3.cn-northwest-1.amazonaws.com.cn/52.82.189.44:443] UNREGISTERED

Expected behavior

When upload large file, the server should not timeout.

The 30 seconds timeout is from the blaze server setting responseHeaderTimeout

The comments says

@param responseHeaderTimeout: Time from when the request is made until a
  *    response line is generated before a 503 response is returned and the
  *    `HttpApp` is canceled

However, the specification does not specify that http header must be passed in 100 response.

Requirements for servers:
A server that receives a 100-continue expectation in an HTTP/1.0 request MUST ignore that expectation.
A server MAY omit sending a 100 (Continue) response if it has already received some or all of the content for the corresponding request, or if the framing indicates that there is no content.
A server that sends a 100 (Continue) response MUST ultimately send a final status code, once it receives and processes the request content, unless the connection is closed prematurely.
A server that responds with a final status code before reading the entire request content SHOULD indicate whether it intends to close the connection (e.g., see Section 9.6 of [HTTP/1.1]) or continue reading the request content.

So does the AWS s3 REST API implented

When upload file, the server respone something like

HTTP/1.1 100 Continue
HTTP/1.1 200 OK
x-amz-id-2: LriYPLdmOdAiIfgSm/F1YsViT1LW94/xUQxMsF7xiEb1a0wiIOIxl+zbwZ163pt7
x-amz-request-id: 0A49CE4060975EAC
x-amz-version-id: default
Date: Wed, 12 Oct 2009 17:50:00 GMT
ETag: "1b2cf535f27731c974343645a3985328"
Content-Length: 0
Connection: close
Server: AmazonS3

It's not a problem when upload small file, however, it will trigger responseHeaderTimeout when upload large file because the server only reponse with HTTP code 100 without any HTTP headers.

One workaround is to increase responseHeaderTimeout time. such as BlazeServerBuilder[F].withResponseHeaderTimeout(5.minutes), but this is not a good solution since it will let other request timeout too late.

I'm not sure how to improve this , perhaps timeout settings should never be use to close a connection that is currently in use, so long-lived connections may remain open longer than this time.