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.

Sign up for GitHub

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

Jump to bottom

HTTP/2: ReadTimeoutException after upgrade from HTTP/1.1 to h2c #1609

Closed
alex-filatov opened this issue Apr 21, 2021 · 0 comments · Fixed by #1612
Closed

HTTP/2: ReadTimeoutException after upgrade from HTTP/1.1 to h2c #1609

alex-filatov opened this issue Apr 21, 2021 · 0 comments · Fixed by #1612
Assignees
@violetagg
Labels
type/bug A general bug
Milestone
1.0.7

Comments

@alex-filatov
Copy link

Actual Behavior

When HttpClient uses h2c protocol with upgrade from HTTP/1.1 and specifies response timeout, HTTP connection is always closed after the timeout regardless of whether response was received or not.

Steps to Reproduce

Server:

DisposableServer server =
        HttpServer.create()
                .port(8080)
                .protocol(H2C, HTTP11)
                .handle((request, response) -> response.sendString(Mono.just("hello")))
                .bindNow();

server.onDispose()
        .block();

Client:

Duration responseTimeout = Duration.ofSeconds(10);

HttpClient client =
        HttpClient.create()
                .baseUrl("http://localhost:8080")
                .protocol(H2C, HTTP11)
//                        .protocol(H2C)
                .responseTimeout(responseTimeout)
                .observe((connection, state) -> System.out.printf("%s %s %s\n", LocalDateTime.now(), state, connection));

client.get().responseContent().aggregate().block();

Thread.sleep(responseTimeout.toMillis() * 2);

client.get().responseContent().aggregate().block();

Output when both H2C and HTTP11 are specified:

14:05:47.084 [connected] PooledConnection{channel=[id: 0x235bbd6c, L:/127.0.0.1:57690 - R:localhost/127.0.0.1:8080]}
14:05:47.086 [configured] GET{uri=/, connection=PooledConnection{channel=[id: 0x235bbd6c, L:/127.0.0.1:57690 - R:localhost/127.0.0.1:8080]}}
14:05:47.089 [request_prepared] GET{uri=/, connection=PooledConnection{channel=[id: 0x235bbd6c, L:/127.0.0.1:57690 - R:localhost/127.0.0.1:8080]}}
14:05:47.108 [request_sent] GET{uri=/, connection=PooledConnection{channel=[id: 0x235bbd6c, L:/127.0.0.1:57690 - R:localhost/127.0.0.1:8080]}}
14:05:47.138 [upgrade_successful] GET{uri=/, connection=PooledConnection{channel=[id: 0x235bbd6c, L:/127.0.0.1:57690 - R:localhost/127.0.0.1:8080]}}
14:05:47.152 [response_received] GET{uri=/, connection=SimpleConnection{channel=[id: 0x235bbd6c, L:/127.0.0.1:57690 - R:localhost/127.0.0.1:8080](H2 - 1)}}
14:05:47.155 [response_completed] GET{uri=/, connection=SimpleConnection{channel=[id: 0x235bbd6c, L:/127.0.0.1:57690 - R:localhost/127.0.0.1:8080](H2 - 1)}}
14:05:47.156 [disconnecting] GET{uri=/, connection=SimpleConnection{channel=[id: 0x235bbd6c, L:/127.0.0.1:57690 - R:localhost/127.0.0.1:8080](H2 - 1)}}
14:05:47.159 [disconnecting] SimpleConnection{channel=[id: 0x235bbd6c, L:/127.0.0.1:57690 - R:localhost/127.0.0.1:8080](H2 - 1)}
Apr 21, 2021 2:05:57 PM io.netty.channel.DefaultChannelPipeline onUnhandledInboundException
WARNING: An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
io.netty.handler.timeout.ReadTimeoutException

14:06:07.162 [connected] PooledConnection{channel=[id: 0x77557015, L:/127.0.0.1:57693 - R:localhost/127.0.0.1:8080]}
14:06:07.162 [configured] GET{uri=/, connection=PooledConnection{channel=[id: 0x77557015, L:/127.0.0.1:57693 - R:localhost/127.0.0.1:8080]}}
14:06:07.163 [request_prepared] GET{uri=/, connection=PooledConnection{channel=[id: 0x77557015, L:/127.0.0.1:57693 - R:localhost/127.0.0.1:8080]}}
14:06:07.164 [request_sent] GET{uri=/, connection=PooledConnection{channel=[id: 0x77557015, L:/127.0.0.1:57693 - R:localhost/127.0.0.1:8080]}}
14:06:07.166 [upgrade_successful] GET{uri=/, connection=PooledConnection{channel=[id: 0x77557015, L:/127.0.0.1:57693 - R:localhost/127.0.0.1:8080]}}
14:06:07.167 [response_received] GET{uri=/, connection=SimpleConnection{channel=[id: 0x77557015, L:/127.0.0.1:57693 - R:localhost/127.0.0.1:8080](H2 - 1)}}
14:06:07.168 [response_completed] GET{uri=/, connection=SimpleConnection{channel=[id: 0x77557015, L:/127.0.0.1:57693 - R:localhost/127.0.0.1:8080](H2 - 1)}}
14:06:07.168 [disconnecting] GET{uri=/, connection=SimpleConnection{channel=[id: 0x77557015, L:/127.0.0.1:57693 - R:localhost/127.0.0.1:8080](H2 - 1)}}
14:06:07.168 [disconnecting] SimpleConnection{channel=[id: 0x77557015, L:/127.0.0.1:57693 - R:localhost/127.0.0.1:8080](H2 - 1)}

Note the ReadTimeoutException caught after 10 seconds (response timeout) and a new connection (first connection is closed due to the exception) for the second request.

Output when only H2C is used (HTTP/2 prior knowledge) or when response timeout is not specified:

14:06:35.784 [connected] PooledConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080]}
14:06:35.805 [stream_configured] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - -1)}}
14:06:35.809 [request_prepared] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - -1)}}
14:06:35.821 [configured] PooledConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080]}
14:06:35.822 [request_sent] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - 3)}}
14:06:35.829 [response_received] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - 3)}}
14:06:35.832 [response_completed] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - 3)}}
14:06:35.832 [disconnecting] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - 3)}}
14:06:35.833 [disconnecting] SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - 3)}
14:06:55.835 [stream_configured] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - -1)}}
14:06:55.836 [request_prepared] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - -1)}}
14:06:55.837 [request_sent] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - 5)}}
14:06:55.839 [response_received] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - 5)}}
14:06:55.839 [response_completed] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - 5)}}
14:06:55.840 [disconnecting] GET{uri=/, connection=SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - 5)}}
14:06:55.840 [disconnecting] SimpleConnection{channel=[id: 0x41cfd2f7, L:/127.0.0.1:57699 - R:localhost/127.0.0.1:8080](H2 - 5)}

This is expected behavior for both cases.

Your Environment

  • Reactor version(s) used: reactor-netty-http:1.0.6
  • JVM version (java -version): 1.8.0_275
  • OS and version (eg. uname -a): Darwin MacBook.local 19.6.0 Darwin Kernel Version 19.6.0: Mon Aug 31 22:12:52 PDT 2020; root:xnu-6153.141.2~1/RELEASE_X86_64 x86_64 i386 MacBookPro16,1 Darwin
@alex-filatov alex-filatov added status/need-triage A new issue that still need to be evaluated as a whole type/bug A general bug labels Apr 21, 2021
@violetagg violetagg removed the status/need-triage A new issue that still need to be evaluated as a whole label Apr 21, 2021
@violetagg violetagg self-assigned this Apr 21, 2021
@violetagg violetagg added this to the 1.0.7 milestone Apr 22, 2021
violetagg added a commit that referenced this issue Apr 26, 2021
@violetagg
HTTP client: When the upgrade from HTTP/1.1 to HTTP/2 clear text is s…
682f805 
…uccessful remove `ResponseTimeoutHandler`

Ensure `ResponseTimeoutHandler` is added to the upgrade stream.

Fixes #1609
@violetagg violetagg mentioned this issue Apr 26, 2021
Merged
violetagg added a commit that referenced this issue Apr 26, 2021
@violetagg
HTTP client: When the upgrade from HTTP/1.1 to HTTP/2 clear text is s…
4b2c7f3 
…uccessful remove `ResponseTimeoutHandler`

Ensure `ResponseTimeoutHandler` is added to the upgrade stream.

Fixes #1609
violetagg added a commit that referenced this issue Apr 26, 2021
@violetagg
HTTP client: When the upgrade from HTTP/1.1 to HTTP/2 clear text is s…
04e6a5c 
…uccessful remove `ResponseTimeoutHandler` (#1612)

Ensure `ResponseTimeoutHandler` is added to the upgrade stream.

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

@violetagg violetagg

Labels
type/bug A general bug
Projects
None yet
Milestone
1.0.7
Development

Successfully merging a pull request may close this issue.

HTTP client: When the upgrade from HTTP/1.1 to HTTP/2 clear text is s… reactor/reactor-netty
2 participants
@violetagg @alex-filatov