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

Support HTTP/2 connections in REST Client Reactive #31192

Merged
merged 2 commits into from
Mar 2, 2023

Conversation

Sgitario
Copy link
Contributor

Relates #13969

@Sgitario Sgitario requested a review from geoand February 15, 2023 15:43
@Sgitario
Copy link
Contributor Author

@pjgg fyi

@@ -294,6 +294,7 @@
<module>rest-client</module>
<module>resteasy-reactive-kotlin</module>
<module>rest-client-reactive</module>
<module>rest-client-reactive-http2</module>
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I know we should avoid adding a new integration test modules, but I think in this case it makes sense since I didn't find any other module where this feature (testing http2 both in server and client side) fits.

Note that the module rest-client-reactive uses Vert.x routes, not the quarkus-resteasy-reactive extension.

Anyway, if you think there is other module that fits better, let me know.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's warranted


public String getHttpVersion() {
return restClientRequestContext.getVertxClientResponse().version().toString();
}
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

To be honest, this was convenient for testing purposes... but I do think it still makes sense as now the HTTP version can be other than HTTP 1.1.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure I follow here

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The problem is that we didn't expose any method to return the HTTP version and I needed it to verify that the HTTP version was the expected in a test.

But in spite of it being convenient for a test, I think it makes sense to keep this method for users as well.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I seriously doubt anyone will ever use it as it's an implementation class method.

In any case, I'm fine with keeping it

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

+1


[source, properties]
----
quarkus.rest-client.http2=true
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm, maybe it should be enable-http2? @gsmet WDYT?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For my understanding, it doesn't make sense to enable HTTP/2 always and let the client negotiate with the server?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually, in vert.x http core this is enabled by default, so it's fine with me to enable http2 by default. Please, confirm if you want me to do this change here.

About, being just http2 or enable-http2, I like more the latter, but in HTTP configuration, it's simply http2. Anyway, let me know what you prefer and I will change it. The same for the alpn property.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You mean in our http configuration for the server? If so, then let's be consistent

Copy link
Contributor Author

@Sgitario Sgitario Feb 15, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, so will keep the current 'http2' and 'alpn' names

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we probably need @cescoffier 's blessing to enable it by default.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

From my point of view and taking into account the number of failures that enabling http2 by default in REST Client has caused, this flag should be disabled by default.

Though I'm trying to find a solution to the Multipart failures, the solution seems to not be trivial as it involves Vert.x client + Netty client (at least, not trivial to me! Since I don't have much experience with either Vert.x or Netty).

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One thing I don't understand is why this now fails if http2 is enabled by default in Vert.x HTTP client

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this is only a client thing that is caused by the QuarkusMultipartFormUpload implementation which internally uses Netty HTTP 1/1. But I'm still investigating.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, thanks

* When the property `http2` is enabled, this flag will be automatically enabled.
*/
@ConfigItem
public Optional<Boolean> alpn;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same comment as the http2 field.

@quarkus-bot

This comment has been minimized.

@github-actions
Copy link

github-actions bot commented Feb 16, 2023

🙈 The PR is closed and the preview is expired.

@Sgitario
Copy link
Contributor Author

Having enabled the http2 breaks the rest-client-multipart integration test:

2023-02-16 09:16:47,194 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-0) HTTP Request to /client/params/byte-array-as-binary-file failed, error id: 84afe8fb-77cf-4774-9a28-037dc80e6dce-1: io.vertx.core.http.StreamResetException: Stream reset: 1

2023-02-16 09:16:47,198 ERROR [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (executor-thread-0) Request failed: io.vertx.core.http.StreamResetException: Stream reset: 1

I'm investigating this.

@Sgitario
Copy link
Contributor Author

Having enabled the http2 breaks the rest-client-multipart integration test:

2023-02-16 09:16:47,194 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-0) HTTP Request to /client/params/byte-array-as-binary-file failed, error id: 84afe8fb-77cf-4774-9a28-037dc80e6dce-1: io.vertx.core.http.StreamResetException: Stream reset: 1

2023-02-16 09:16:47,198 ERROR [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (executor-thread-0) Request failed: io.vertx.core.http.StreamResetException: Stream reset: 1

I'm investigating this.

I've just found the issue in

I need to find a solution to this.

@quarkus-bot

This comment has been minimized.

@Sgitario
Copy link
Contributor Author

The problem seems to be related to subsequent POST calls containing form parts. The first call works, but the second fails. See below a complete traces with further information.

2023-02-16 19:18:12,605 DEBUG [org.apa.htt.imp.con.DefaultClientConnection] (main) Sending request: GET /client/byte-array-as-binary-file HTTP/1.1
2023-02-16 19:18:12,606 DEBUG [org.apa.htt.wire] (main)  >> "GET /client/byte-array-as-binary-file HTTP/1.1[\r][\n]"
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.wire] (main)  >> "Content-Type: text/plain; charset=ISO-8859-1[\r][\n]"
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.wire] (main)  >> "Accept: */*[\r][\n]"
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.wire] (main)  >> "Host: localhost:8081[\r][\n]"
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.wire] (main)  >> "Connection: Keep-Alive[\r][\n]"
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.wire] (main)  >> "User-Agent: Apache-HttpClient/4.5.14 (Java/11.0.17)[\r][\n]"
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.wire] (main)  >> "Accept-Encoding: gzip,deflate[\r][\n]"
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.wire] (main)  >> "[\r][\n]"
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.headers] (main) >> GET /client/byte-array-as-binary-file HTTP/1.1
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.headers] (main) >> Content-Type: text/plain; charset=ISO-8859-1
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.headers] (main) >> Accept: */*
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.headers] (main) >> Host: localhost:8081
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.headers] (main) >> Connection: Keep-Alive
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.headers] (main) >> User-Agent: Apache-HttpClient/4.5.14 (Java/11.0.17)
2023-02-16 19:18:12,607 DEBUG [org.apa.htt.headers] (main) >> Accept-Encoding: gzip,deflate
2023-02-16 19:18:12,610 DEBUG [io.net.uti.Recycler] (vert.x-eventloop-thread-1) -Dio.netty.recycler.maxCapacityPerThread: 4096
2023-02-16 19:18:12,610 DEBUG [io.net.uti.Recycler] (vert.x-eventloop-thread-1) -Dio.netty.recycler.ratio: 8
2023-02-16 19:18:12,610 DEBUG [io.net.uti.Recycler] (vert.x-eventloop-thread-1) -Dio.netty.recycler.chunkSize: 32
2023-02-16 19:18:12,610 DEBUG [io.net.uti.Recycler] (vert.x-eventloop-thread-1) -Dio.netty.recycler.blocking: false
2023-02-16 19:18:12,616 DEBUG [io.net.buf.AbstractByteBuf] (vert.x-eventloop-thread-1) -Dio.netty.buffer.checkAccessible: true
2023-02-16 19:18:12,616 DEBUG [io.net.buf.AbstractByteBuf] (vert.x-eventloop-thread-1) -Dio.netty.buffer.checkBounds: true
2023-02-16 19:18:12,617 DEBUG [io.net.uti.ResourceLeakDetectorFactory] (vert.x-eventloop-thread-1) Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@77847b20
2023-02-16 19:18:12,664 DEBUG [io.net.han.cod.com.ZlibCodecFactory] (vert.x-eventloop-thread-1) -Dio.netty.noJdkZlibDecoder: false
2023-02-16 19:18:12,665 DEBUG [io.net.han.cod.com.ZlibCodecFactory] (vert.x-eventloop-thread-1) -Dio.netty.noJdkZlibEncoder: false
2023-02-16 19:18:12,995 DEBUG [org.jbo.res.rea.cli.log.DefaultClientLogger] (vert.x-eventloop-thread-1) Request: POST http://localhost:8081/echo/binary Headers[Accept=text/plain;charset=UTF-8 Content-Type=multipart/form-data; boundary=48403637be2a459 transfer-encoding=chunked User-Agent=Resteasy Reactive Client], Body omitted
2023-02-16 19:18:13,031 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 281B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 50 4f 53 54 20 2f 65 63 68 6f 2f 62 69 6e 61 72 |POST /echo/binar|
|00000010| 79 20 48 54 54 50 2f 31 2e 31 0d 0a 41 63 63 65 |y HTTP/1.1..Acce|
|00000020| 70 74 3a 20 74 65 78 74 2f 70 6c 61 69 6e 3b 63 |pt: text/plain;c|
|00000030| 68 61 72 73 65 74 3d 55 54 46 2d 38 0d 0a 43 6f |harset=UTF-8..Co|
|00000040| 6e 74 65 6e 74 2d 54 79 70 65 3a 20 6d 75 6c 74 |ntent-Type: mult|
|00000050| 69 70 61 72 74 2f 66 6f 72 6d 2d 64 61 74 61 3b |ipart/form-data;|
|00000060| 20 62 6f 75 6e 64 61 72 79 3d 34 38 34 30 33 36 | boundary=484036|
|00000070| 33 37 62 65 32 61 34 35 39 0d 0a 55 73 65 72 2d |37be2a459..User-|
|00000080| 41 67 65 6e 74 3a 20 52 65 73 74 65 61 73 79 20 |Agent: Resteasy |
|00000090| 52 65 61 63 74 69 76 65 20 43 6c 69 65 6e 74 0d |Reactive Client.|
|000000a0| 0a 68 6f 73 74 3a 20 6c 6f 63 61 6c 68 6f 73 74 |.host: localhost|
|000000b0| 3a 38 30 38 31 0d 0a 74 72 61 6e 73 66 65 72 2d |:8081..transfer-|
|000000c0| 65 6e 63 6f 64 69 6e 67 3a 20 63 68 75 6e 6b 65 |encoding: chunke|
|000000d0| 64 0d 0a 75 70 67 72 61 64 65 3a 20 68 32 63 0d |d..upgrade: h2c.|
|000000e0| 0a 48 54 54 50 32 2d 53 65 74 74 69 6e 67 73 3a |.HTTP2-Settings:|
|000000f0| 20 0d 0a 63 6f 6e 6e 65 63 74 69 6f 6e 3a 20 48 | ..connection: H|
|00000100| 54 54 50 32 2d 53 65 74 74 69 6e 67 73 2c 75 70 |TTP2-Settings,up|
|00000110| 67 72 61 64 65 0d 0a 0d 0a                      |grade....       |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,033 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 5B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 31 36 35 0d 0a                                  |165..           |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,036 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 357B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 2d 2d 34 38 34 30 33 36 33 37 62 65 32 61 34 35 |--48403637be2a45|
|00000010| 39 0d 0a 63 6f 6e 74 65 6e 74 2d 64 69 73 70 6f |9..content-dispo|
|00000020| 73 69 74 69 6f 6e 3a 20 66 6f 72 6d 2d 64 61 74 |sition: form-dat|
|00000030| 61 3b 20 6e 61 6d 65 3d 22 66 69 6c 65 22 3b 20 |a; name="file"; |
|00000040| 66 69 6c 65 6e 61 6d 65 3d 22 66 69 6c 65 22 0d |filename="file".|
|00000050| 0a 63 6f 6e 74 65 6e 74 2d 6c 65 6e 67 74 68 3a |.content-length:|
|00000060| 20 31 31 0d 0a 63 6f 6e 74 65 6e 74 2d 74 79 70 | 11..content-typ|
|00000070| 65 3a 20 61 70 70 6c 69 63 61 74 69 6f 6e 2f 6f |e: application/o|
|00000080| 63 74 65 74 2d 73 74 72 65 61 6d 0d 0a 63 6f 6e |ctet-stream..con|
|00000090| 74 65 6e 74 2d 74 72 61 6e 73 66 65 72 2d 65 6e |tent-transfer-en|
|000000a0| 63 6f 64 69 6e 67 3a 20 62 69 6e 61 72 79 0d 0a |coding: binary..|
|000000b0| 0d 0a 48 45 4c 4c 4f 20 57 4f 52 4c 44 0d 0a 2d |..HELLO WORLD..-|
|000000c0| 2d 34 38 34 30 33 36 33 37 62 65 32 61 34 35 39 |-48403637be2a459|
|000000d0| 0d 0a 63 6f 6e 74 65 6e 74 2d 64 69 73 70 6f 73 |..content-dispos|
|000000e0| 69 74 69 6f 6e 3a 20 66 6f 72 6d 2d 64 61 74 61 |ition: form-data|
|000000f0| 3b 20 6e 61 6d 65 3d 22 66 69 6c 65 4e 61 6d 65 |; name="fileName|
|00000100| 22 0d 0a 63 6f 6e 74 65 6e 74 2d 6c 65 6e 67 74 |"..content-lengt|
|00000110| 68 3a 20 31 32 0d 0a 63 6f 6e 74 65 6e 74 2d 74 |h: 12..content-t|
|00000120| 79 70 65 3a 20 74 65 78 74 2f 70 6c 61 69 6e 3b |ype: text/plain;|
|00000130| 20 63 68 61 72 73 65 74 3d 55 54 46 2d 38 0d 0a | charset=UTF-8..|
|00000140| 0d 0a 67 72 65 65 74 69 6e 67 2e 74 78 74 0d 0a |..greeting.txt..|
|00000150| 2d 2d 34 38 34 30 33 36 33 37 62 65 32 61 34 35 |--48403637be2a45|
|00000160| 39 2d 2d 0d 0a                                  |9--..           |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,036 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 2B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 0d 0a                                           |..              |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,037 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,039 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 0B
2023-02-16 19:18:13,039 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,039 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 5B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 30 0d 0a 0d 0a                                  |0....           |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,039 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,040 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] USER_EVENT: java.lang.Object@3cea1850
2023-02-16 19:18:13,042 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] ACTIVE
2023-02-16 19:18:13,043 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ: 71B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 48 54 54 50 2f 31 2e 31 20 31 30 31 20 53 77 69 |HTTP/1.1 101 Swi|
|00000010| 74 63 68 69 6e 67 20 50 72 6f 74 6f 63 6f 6c 73 |tching Protocols|
|00000020| 0d 0a 63 6f 6e 6e 65 63 74 69 6f 6e 3a 20 75 70 |..connection: up|
|00000030| 67 72 61 64 65 0d 0a 75 70 67 72 61 64 65 3a 20 |grade..upgrade: |
|00000040| 68 32 63 0d 0a 0d 0a                            |h2c....         |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,074 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 24B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a |PRI * HTTP/2.0..|
|00000010| 0d 0a 53 4d 0d 0a 0d 0a                         |..SM....        |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,075 DEBUG [io.net.han.cod.htt.Http2FrameLogger] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] OUTBOUND SETTINGS: ack=false settings={MAX_HEADER_LIST_SIZE=8192}
2023-02-16 19:18:13,075 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 15B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 06 04 00 00 00 00 00 00 06 00 00 20 00    |............. . |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,077 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,077 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ COMPLETE
2023-02-16 19:18:13,077 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,088 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ: 21B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 0c 04 00 00 00 00 00 00 03 00 00 00 64 00 |..............d.|
|00000010| 06 00 00 20 00                                  |... .           |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,089 DEBUG [io.net.han.cod.htt.Http2FrameLogger] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] INBOUND SETTINGS: ack=false settings={MAX_CONCURRENT_STREAMS=100, MAX_HEADER_LIST_SIZE=8192}
2023-02-16 19:18:13,090 DEBUG [io.net.han.cod.htt.Http2FrameLogger] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] OUTBOUND SETTINGS: ack=true
2023-02-16 19:18:13,090 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 9B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 04 01 00 00 00 00                      |.........       |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,092 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ COMPLETE
2023-02-16 19:18:13,092 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,092 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ: 9B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 04 01 00 00 00 00                      |.........       |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,092 DEBUG [io.net.han.cod.htt.Http2FrameLogger] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] INBOUND SETTINGS: ack=true
2023-02-16 19:18:13,092 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ COMPLETE
2023-02-16 19:18:13,093 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,101 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ: 45B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 24 01 24 00 00 00 01 00 00 00 00 0f 88 5c |..$.$..........\|
|00000010| 02 32 33 5f 18 74 65 78 74 2f 70 6c 61 69 6e 3b |.23_.text/plain;|
|00000020| 63 68 61 72 73 65 74 3d 55 54 46 2d 38          |charset=UTF-8   |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,103 DEBUG [io.net.han.cod.htt.Http2FrameLogger] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] INBOUND HEADERS: streamId=1 headers=DefaultHttp2Headers[:status: 200, content-length: 23, content-type: text/plain;charset=UTF-8] streamDependency=0 weight=16 exclusive=false padding=0 endStream=false
2023-02-16 19:18:13,106 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ COMPLETE
2023-02-16 19:18:13,106 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,106 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ: 32B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 17 00 01 00 00 00 01 66 69 6c 65 4f 6b 3a |.........fileOk:|
|00000010| 74 72 75 65 2c 6e 61 6d 65 4f 6b 3a 74 72 75 65 |true,nameOk:true|
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,107 DEBUG [io.net.han.cod.htt.Http2FrameLogger] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] INBOUND DATA: streamId=1 padding=0 endStream=true length=23 bytes=66696c654f6b3a747275652c6e616d654f6b3a74727565
2023-02-16 19:18:13,108 DEBUG [org.jbo.res.rea.cli.log.DefaultClientLogger] (vert.x-eventloop-thread-1) Response: POST http://localhost:8081/echo/binary, Status[200 OK], Headers[content-type=text/plain;charset=UTF-8 content-length=23], Body:
fileOk:true,nameOk:true
2023-02-16 19:18:13,109 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ COMPLETE
2023-02-16 19:18:13,109 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,116 DEBUG [org.apa.htt.wire] (main)  << "HTTP/1.1 200 OK[\r][\n]"
2023-02-16 19:18:13,117 DEBUG [org.apa.htt.wire] (main)  << "content-length: 23[\r][\n]"
2023-02-16 19:18:13,117 DEBUG [org.apa.htt.wire] (main)  << "Content-Type: text/plain;charset=UTF-8[\r][\n]"
2023-02-16 19:18:13,118 DEBUG [org.apa.htt.wire] (main)  << "[\r][\n]"
2023-02-16 19:18:13,118 DEBUG [org.apa.htt.imp.con.DefaultClientConnection] (main) Receiving response: HTTP/1.1 200 OK
2023-02-16 19:18:13,118 DEBUG [org.apa.htt.headers] (main) << HTTP/1.1 200 OK
2023-02-16 19:18:13,118 DEBUG [org.apa.htt.headers] (main) << content-length: 23
2023-02-16 19:18:13,118 DEBUG [org.apa.htt.headers] (main) << Content-Type: text/plain;charset=UTF-8
2023-02-16 19:18:13,120 DEBUG [org.apa.htt.imp.cli.DefaultHttpClient] (main) Connection can be kept alive indefinitely
2023-02-16 19:18:13,139 DEBUG [io.res.int.RequestSpecificationImpl$RestAssuredHttpBuilder] (main) Parsing response as: text/plain;charset=UTF-8
2023-02-16 19:18:13,139 DEBUG [io.res.int.RequestSpecificationImpl$RestAssuredHttpBuilder] (main) Parsed data to instance of: class org.apache.http.conn.EofSensorInputStream
2023-02-16 19:18:13,212 DEBUG [org.apa.htt.wire] (main)  << "fileOk:true,nameOk:true"
2023-02-16 19:18:13,213 DEBUG [org.apa.htt.imp.con.BasicClientConnectionManager] (main) Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@41e8d917
2023-02-16 19:18:13,214 DEBUG [org.apa.htt.imp.con.BasicClientConnectionManager] (main) Connection can be kept alive indefinitely
2023-02-16 19:18:13,244 DEBUG [org.apa.htt.imp.con.BasicClientConnectionManager] (main) Get connection for route {}->http://localhost:8081
2023-02-16 19:18:13,245 DEBUG [org.apa.htt.imp.con.DefaultClientConnectionOperator] (main) Connecting to localhost:8081
2023-02-16 19:18:13,246 DEBUG [org.apa.htt.cli.pro.RequestAddCookies] (main) CookieSpec selected: ignoreCookies
2023-02-16 19:18:13,246 DEBUG [org.apa.htt.cli.pro.RequestAuthCache] (main) Auth cache not set in the context
2023-02-16 19:18:13,246 DEBUG [org.apa.htt.cli.pro.RequestTargetAuthentication] (main) Target auth state: UNCHALLENGED
2023-02-16 19:18:13,246 DEBUG [org.apa.htt.cli.pro.RequestProxyAuthentication] (main) Proxy auth state: UNCHALLENGED
2023-02-16 19:18:13,246 DEBUG [org.apa.htt.imp.cli.DefaultHttpClient] (main) Attempt 1 to execute request
2023-02-16 19:18:13,246 DEBUG [org.apa.htt.imp.con.DefaultClientConnection] (main) Sending request: GET /client/params/byte-array-as-binary-file HTTP/1.1
2023-02-16 19:18:13,246 DEBUG [org.apa.htt.wire] (main)  >> "GET /client/params/byte-array-as-binary-file HTTP/1.1[\r][\n]"
2023-02-16 19:18:13,246 DEBUG [org.apa.htt.wire] (main)  >> "Content-Type: text/plain; charset=ISO-8859-1[\r][\n]"
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.wire] (main)  >> "Accept: */*[\r][\n]"
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.wire] (main)  >> "Host: localhost:8081[\r][\n]"
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.wire] (main)  >> "Connection: Keep-Alive[\r][\n]"
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.wire] (main)  >> "User-Agent: Apache-HttpClient/4.5.14 (Java/11.0.17)[\r][\n]"
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.wire] (main)  >> "Accept-Encoding: gzip,deflate[\r][\n]"
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.wire] (main)  >> "[\r][\n]"
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.headers] (main) >> GET /client/params/byte-array-as-binary-file HTTP/1.1
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.headers] (main) >> Content-Type: text/plain; charset=ISO-8859-1
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.headers] (main) >> Accept: */*
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.headers] (main) >> Host: localhost:8081
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.headers] (main) >> Connection: Keep-Alive
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.headers] (main) >> User-Agent: Apache-HttpClient/4.5.14 (Java/11.0.17)
2023-02-16 19:18:13,247 DEBUG [org.apa.htt.headers] (main) >> Accept-Encoding: gzip,deflate
2023-02-16 19:18:13,260 DEBUG [org.jbo.res.rea.cli.log.DefaultClientLogger] (vert.x-eventloop-thread-1) Request: POST http://localhost:8081/echo/binary Headers[Accept=text/plain;charset=UTF-8 Content-Type=multipart/form-data; boundary=b0dacd84a9412491 transfer-encoding=chunked User-Agent=Resteasy Reactive Client], Body omitted
2023-02-16 19:18:13,263 DEBUG [io.net.han.cod.htt.Http2FrameLogger] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] OUTBOUND HEADERS: streamId=3 headers=DefaultHttp2Headers[:method: POST, :path: /echo/binary, :scheme: http, :authority: localhost:8081, accept: text/plain;charset=UTF-8, content-type: multipart/form-data; boundary=b0dacd84a9412491, transfer-encoding: chunked, user-agent: Resteasy Reactive Client] streamDependency=0 weight=16 exclusive=false padding=0 endStream=false
2023-02-16 19:18:13,264 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 14B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 92 01 24 00 00 00 03 00 00 00 00 0f       |....$.........  |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,264 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 141B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 83 44 0c 2f 65 63 68 6f 2f 62 69 6e 61 72 79 86 |.D./echo/binary.|
|00000010| 41 0e 6c 6f 63 61 6c 68 6f 73 74 3a 38 30 38 31 |A.localhost:8081|
|00000020| 53 18 74 65 78 74 2f 70 6c 61 69 6e 3b 63 68 61 |S.text/plain;cha|
|00000030| 72 73 65 74 3d 55 54 46 2d 38 5f 2e 6d 75 6c 74 |rset=UTF-8_.mult|
|00000040| 69 70 61 72 74 2f 66 6f 72 6d 2d 64 61 74 61 3b |ipart/form-data;|
|00000050| 20 62 6f 75 6e 64 61 72 79 3d 62 30 64 61 63 64 | boundary=b0dacd|
|00000060| 38 34 61 39 34 31 32 34 39 31 79 07 63 68 75 6e |84a9412491y.chun|
|00000070| 6b 65 64 7a 18 52 65 73 74 65 61 73 79 20 52 65 |kedz.Resteasy Re|
|00000080| 61 63 74 69 76 65 20 43 6c 69 65 6e 74          |active Client   |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,264 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,265 DEBUG [io.net.han.cod.htt.Http2FrameLogger] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] OUTBOUND DATA: streamId=3 padding=0 endStream=false length=360 bytes=2d2d623064616364383461393431323439310d0a636f6e74656e742d646973706f736974696f6e3a20666f726d2d646174613b206e616d653d2266696c65223b...
2023-02-16 19:18:13,265 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 9B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 01 68 00 00 00 00 00 03                      |..h......       |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,266 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 360B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 2d 2d 62 30 64 61 63 64 38 34 61 39 34 31 32 34 |--b0dacd84a94124|
|00000010| 39 31 0d 0a 63 6f 6e 74 65 6e 74 2d 64 69 73 70 |91..content-disp|
|00000020| 6f 73 69 74 69 6f 6e 3a 20 66 6f 72 6d 2d 64 61 |osition: form-da|
|00000030| 74 61 3b 20 6e 61 6d 65 3d 22 66 69 6c 65 22 3b |ta; name="file";|
|00000040| 20 66 69 6c 65 6e 61 6d 65 3d 22 66 69 6c 65 22 | filename="file"|
|00000050| 0d 0a 63 6f 6e 74 65 6e 74 2d 6c 65 6e 67 74 68 |..content-length|
|00000060| 3a 20 31 31 0d 0a 63 6f 6e 74 65 6e 74 2d 74 79 |: 11..content-ty|
|00000070| 70 65 3a 20 61 70 70 6c 69 63 61 74 69 6f 6e 2f |pe: application/|
|00000080| 6f 63 74 65 74 2d 73 74 72 65 61 6d 0d 0a 63 6f |octet-stream..co|
|00000090| 6e 74 65 6e 74 2d 74 72 61 6e 73 66 65 72 2d 65 |ntent-transfer-e|
|000000a0| 6e 63 6f 64 69 6e 67 3a 20 62 69 6e 61 72 79 0d |ncoding: binary.|
|000000b0| 0a 0d 0a 48 45 4c 4c 4f 20 57 4f 52 4c 44 0d 0a |...HELLO WORLD..|
|000000c0| 2d 2d 62 30 64 61 63 64 38 34 61 39 34 31 32 34 |--b0dacd84a94124|
|000000d0| 39 31 0d 0a 63 6f 6e 74 65 6e 74 2d 64 69 73 70 |91..content-disp|
|000000e0| 6f 73 69 74 69 6f 6e 3a 20 66 6f 72 6d 2d 64 61 |osition: form-da|
|000000f0| 74 61 3b 20 6e 61 6d 65 3d 22 66 69 6c 65 4e 61 |ta; name="fileNa|
|00000100| 6d 65 22 0d 0a 63 6f 6e 74 65 6e 74 2d 6c 65 6e |me"..content-len|
|00000110| 67 74 68 3a 20 31 32 0d 0a 63 6f 6e 74 65 6e 74 |gth: 12..content|
|00000120| 2d 74 79 70 65 3a 20 74 65 78 74 2f 70 6c 61 69 |-type: text/plai|
|00000130| 6e 3b 20 63 68 61 72 73 65 74 3d 55 54 46 2d 38 |n; charset=UTF-8|
|00000140| 0d 0a 0d 0a 67 72 65 65 74 69 6e 67 2e 74 78 74 |....greeting.txt|
|00000150| 0d 0a 2d 2d 62 30 64 61 63 64 38 34 61 39 34 31 |..--b0dacd84a941|
|00000160| 32 34 39 31 2d 2d 0d 0a                         |2491--..        |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,266 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,267 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 0B
2023-02-16 19:18:13,267 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,268 DEBUG [io.net.han.cod.htt.Http2FrameLogger] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] OUTBOUND DATA: streamId=3 padding=0 endStream=true length=0 bytes=
2023-02-16 19:18:13,268 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 9B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 00 01 00 00 00 03                      |.........       |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,268 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] WRITE: 0B
2023-02-16 19:18:13,268 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,269 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ: 13B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 04 03 00 00 00 00 03 00 00 00 01          |.............   |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,269 DEBUG [io.net.han.cod.htt.Http2FrameLogger] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] INBOUND RST_STREAM: streamId=3 errorCode=1
2023-02-16 19:18:13,270 DEBUG [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (vert.x-eventloop-thread-1) Restarting handler chain for exception exception: io.vertx.core.http.StreamResetException: Stream reset: 1

2023-02-16 19:18:13,271 DEBUG [io.net.han.cod.htt.Http2ConnectionHandler] (vert.x-eventloop-thread-0) [id: 0xa654b1d9, L:/127.0.0.1:8081 - R:/127.0.0.1:47888] Sent GOAWAY: lastStreamId '2147483647', errorCode '1', debugData 'Stream 3 does not exist'. Forcing shutdown of the connection.
2023-02-16 19:18:13,271 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ COMPLETE
2023-02-16 19:18:13,271 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,272 DEBUG [org.jbo.res.rea.cli.han.ClientErrorHandler] (vert.x-eventloop-thread-1) Failure: POST http://localhost:8081/echo/binary, Error[Stream reset: 1]: io.vertx.core.http.StreamResetException: Stream reset: 1

2023-02-16 19:18:13,273 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ: 40B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 1f 07 00 00 00 00 00 7f ff ff ff 00 00 00 |................|
|00000010| 01 53 74 72 65 61 6d 20 33 20 64 6f 65 73 20 6e |.Stream 3 does n|
|00000020| 6f 74 20 65 78 69 73 74                         |ot exist        |
+--------+-------------------------------------------------+----------------+
2023-02-16 19:18:13,272 DEBUG [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (executor-thread-0) Restarting handler chain for exception exception: io.vertx.core.http.StreamResetException: Stream reset: 1

2023-02-16 19:18:13,273 DEBUG [io.net.han.cod.htt.Http2FrameLogger] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] INBOUND GO_AWAY: lastStreamId=2147483647 errorCode=1 length=23 bytes=53747265616d203320646f6573206e6f74206578697374
2023-02-16 19:18:13,273 DEBUG [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (executor-thread-0) Attempting to handle unrecoverable exception: io.vertx.core.http.StreamResetException: Stream reset: 1

2023-02-16 19:18:13,273 DEBUG [io.ver.ext.web.RoutingContext] (executor-thread-0) RoutingContext failure (500): io.vertx.core.http.StreamResetException: Stream reset: 1

2023-02-16 19:18:13,275 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ COMPLETE
2023-02-16 19:18:13,275 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,275 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] READ COMPLETE
2023-02-16 19:18:13,276 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 - R:localhost/127.0.0.1:8081] FLUSH
2023-02-16 19:18:13,276 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 ! R:localhost/127.0.0.1:8081] INACTIVE
2023-02-16 19:18:13,276 DEBUG [io.net.han.log.LoggingHandler] (vert.x-eventloop-thread-1) [id: 0xe97969b0, L:/127.0.0.1:47888 ! R:localhost/127.0.0.1:8081] UNREGISTERED
2023-02-16 19:18:13,284 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-0) HTTP Request to /client/params/byte-array-as-binary-file failed, error id: c74af6a7-1cdf-46ee-9138-f8d0c6ef2841-1: io.vertx.core.http.StreamResetException: Stream reset: 1

2023-02-16 19:18:13,285 ERROR [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (executor-thread-0) Request failed: io.vertx.core.http.StreamResetException: Stream reset: 1

2023-02-16 19:18:13,286 DEBUG [org.apa.htt.wire] (main)  << "HTTP/1.1 500 Internal Server Error[\r][\n]"
2023-02-16 19:18:13,286 DEBUG [org.apa.htt.wire] (main)  << "content-type: application/json; charset=utf-8[\r][\n]"
2023-02-16 19:18:13,286 DEBUG [org.apa.htt.wire] (main)  << "content-length: 186[\r][\n]"
2023-02-16 19:18:13,286 DEBUG [org.apa.htt.wire] (main)  << "[\r][\n]"
2023-02-16 19:18:13,286 DEBUG [org.apa.htt.imp.con.DefaultClientConnection] (main) Receiving response: HTTP/1.1 500 Internal Server Error
2023-02-16 19:18:13,286 DEBUG [org.apa.htt.headers] (main) << HTTP/1.1 500 Internal Server Error
2023-02-16 19:18:13,286 DEBUG [org.apa.htt.headers] (main) << content-type: application/json; charset=utf-8
2023-02-16 19:18:13,286 DEBUG [org.apa.htt.headers] (main) << content-length: 186
2023-02-16 19:18:13,286 DEBUG [org.apa.htt.imp.cli.DefaultHttpClient] (main) Connection can be kept alive indefinitely
2023-02-16 19:18:13,287 DEBUG [io.res.int.RequestSpecificationImpl$RestAssuredHttpBuilder] (main) Parsing response as: application/json; charset=utf-8
2023-02-16 19:18:13,287 DEBUG [io.res.int.RequestSpecificationImpl$RestAssuredHttpBuilder] (main) Parsed data to instance of: class org.apache.http.conn.EofSensorInputStream

@Sgitario
Copy link
Contributor Author

Sgitario commented Feb 16, 2023

It seems Vert.x fails to find the streamId and then reset the stream, but I don't see why it only happens in the second call. @gsmet @geoand @cescoffier do you know somebody from the Vert.x team who can help here?

I also see that there are similar issues to this:

@geoand
Copy link
Contributor

geoand commented Feb 17, 2023

cc @tsegismont @vietj

@Sgitario
Copy link
Contributor Author

I've found the root cause of this issue: the http2 decoder fails to validate the HTTP headers in the second call because somehow it has transfer-encoding=chunked which is invalid for HTTP/2.

@Sgitario Sgitario marked this pull request as draft February 17, 2023 10:11
@Sgitario
Copy link
Contributor Author

My guess is that Vert.x is adding the HTTP/2 handlers after the first request is made and then it understand the next requests are HTTP/2 requests, so it fails because the transfer-encoding=chunked is invalid. Maybe, we're clearing the context correctly or this is indeed a Vert.x, hopefully @tsegismont @vietj can help here.

By the way, to reproduce this issue, you can build the changes in this pull request (mvn clean install -Dquickly) and then:

  • go to integration-tests/rest-client-reactive-multipart
  • and run simple one test: mvn clean install -Dtest=MultipartResourceTest#shouldSendByteArrayAsBinaryFile

However, when we don't set the transfer-encoding=chunked ever (see commit: 926378a). This makes it work most of the tests in this module for HTTP/2 and also HTTP/1.1. I also tested when the requests are split into multiple chunks using a large file and everything looks good...

After this change, the only test that keeps failing is: MultipartResourceTest#shouldMultiAsBinaryFile which fails with:

Caused by: java.io.IOException: io.netty.handler.codec.http2.Http2Exception: HTTP/2 client preface string missing or corrupt. Hex dump for received bytes: 383866376538382d2d0d0a
		at org.jboss.resteasy.reactive.server.vertx.VertxInputStream$VertxBlockingInput$2.handle(VertxInputStream.java:202)
		at org.jboss.resteasy.reactive.server.vertx.VertxInputStream$VertxBlockingInput$2.handle(VertxInputStream.java:198)
		at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
		at io.vertx.core.http.impl.HttpEventHandler.handleException(HttpEventHandler.java:89)
		at io.vertx.core.http.impl.Http2ServerRequest.notifyException(Http2ServerRequest.java:150)
		at io.vertx.core.http.impl.Http2ServerRequest.handleException(Http2ServerRequest.java:135)
		at io.vertx.core.http.impl.Http2ServerStream.handleException(Http2ServerStream.java:161)
		at io.vertx.core.http.impl.Http2ConnectionBase.lambda$onConnectionError$1(Http2ConnectionBase.java:120)
		at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
		at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:246)
		at io.vertx.core.http.impl.Http2ConnectionBase.onConnectionError(Http2ConnectionBase.java:120)
		at io.vertx.core.http.impl.VertxHttp2ConnectionHandler.onConnectionError(VertxHttp2ConnectionHandler.java:159)
		at io.netty.handler.codec.http2.Http2ConnectionHandler.onError(Http2ConnectionHandler.java:656)
		at io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.decode(Http2ConnectionHandler.java:253)
		at io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:453)
		at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529)
		at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468)
		at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)

@quarkus-bot

This comment has been minimized.

@Sgitario
Copy link
Contributor Author

Reported issue in Vert.x: eclipse-vertx/vert.x#4618

@Sgitario
Copy link
Contributor Author

I've just updated the pull request and fixed all the issues with Vert.x which I reported:

I could workaround this issue by manually adapting the request (the only issues were about the path header that needs to finish with \ and the content-encoding=chunked is invalid in HTTP/2).

This is a minor issue, but users would notice a different behavior. At the moment, we cannot map the HttpClosedException to remap it to a TimeoutException as it's happening in HTTP 1.1.

@quarkus-bot

This comment has been minimized.

@Sgitario
Copy link
Contributor Author

Sgitario commented Feb 24, 2023

The failures are caused by eclipse-vertx/vert.x#4630 and eclipse-vertx/vert.x#4631.

@quarkus-bot

This comment has been minimized.

@Sgitario
Copy link
Contributor Author

The BuildIT is unrelated to these changes. Rebasing.

@Sgitario
Copy link
Contributor Author

Sgitario commented Feb 27, 2023

@geoand @gsmet @cescoffier I've fixed all the issues we got with using HTTP2 in RESTeasy reactive client, so it should be good to proceed.
However, I think we should turn it off by default because of all the issues I've found in Vert.x and that hopefully will be in 4.4.0:

  • Only the first request is upgraded to HTTP2. So, when we reuse the same connection, the first request might work fine, but not the second (this is because Vert.x automatically adapts the first request, but not the second). Also, Vert.x does not provide information about why the second request failed (it only throws io.vertx.core.http.StreamResetException: Stream reset: 1). One reason could be that the headers are not valid (example: sending transfer-encoding=chunked), and another reason could be that the request path is empty (this has been already fixed in Vert.x here and will be part of 4.4.0) More info about this issue here.

  • We won't know when a request timeout occurs. Vert.x will always throw an HttpClosedException exception with no more information. So, when using HTTP 1.1, we'll see a TimeoutException, and in HTTP 2, we'll see an HttpClosedException. This is a change of behavior that at least we should document. Reported in here.

  • Vert.x does not trace the spans well when upgrading connections. I've found two issues: End of the trace is missing the response status and When upgrading connection, the first request does not generate the spans of kind CLIENT. The Latter should be fixed by this pull request.

Therefore, are you good to disable HTTP2 by default and proceed with this pull request?

@geoand
Copy link
Contributor

geoand commented Feb 27, 2023

👌

@Sgitario
Copy link
Contributor Author

I will wait for you all before disabling http2 by default in the reactive rest-client

@quarkus-bot

This comment has been minimized.

@gsmet
Copy link
Member

gsmet commented Feb 27, 2023

@Sgitario I agree it's the best solution for now.

/cc @cescoffier for further validation of what @Sgitario is saying here: #31192 (comment) .

@cescoffier
Copy link
Member

Yea, go ahead and disable by default.

@@ -343,6 +343,11 @@ public void setContentTransferEncoding(String contentTransferEncoding) {
this.contentTransferEncoding = contentTransferEncoding;
}

@Override
public long length() {
return buffer.readableBytes() + super.length();
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The content-length was missing the buffer bytes. HTTP/1.1 was ok with this, but HTTP/2 is much stricter.

counter.incrementAndGet();
boolean writable = pending.write(buff);
if (encoder.isEndOfInput()) {
} else if (chunk == LastHttpContent.EMPTY_LAST_CONTENT || encoder.isEndOfInput()) {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This will save up to send an empty request to the server.

@Sgitario
Copy link
Contributor Author

Sgitario commented Feb 27, 2023

PR updated by:

  • Disabling http2 by default
  • Including some of the multipart tests into the new module http2 which helped to spot some issues with HTTP2

@Sgitario Sgitario requested a review from gsmet February 27, 2023 15:43
@quarkus-bot

This comment has been minimized.

@quarkus-bot
Copy link

quarkus-bot bot commented Feb 28, 2023

Failing Jobs - Building a9a6c97

Status Name Step Failures Logs Raw logs
Maven Tests - JDK 11 Build Failures Logs Raw logs
Maven Tests - JDK 11 Windows Build Failures Logs Raw logs

Full information is available in the Build summary check run.

Failures

⚙️ Maven Tests - JDK 11 #

- Failing: integration-tests/maven 

📦 integration-tests/maven

io.quarkus.maven.it.BuildIT.testClassLoaderLinkageError line 102 - More details - Source on GitHub

org.opentest4j.AssertionFailedError: 

expected: 0

io.quarkus.maven.it.BuildIT.testClassLoaderLinkageError line 102 - More details - Source on GitHub

org.opentest4j.AssertionFailedError: 

expected: 0

⚙️ Maven Tests - JDK 11 Windows #

📦 integration-tests/maven

io.quarkus.maven.it.BuildIT.testClassLoaderLinkageError line 102 - More details - Source on GitHub

org.opentest4j.AssertionFailedError: 

expected: 0

io.quarkus.maven.it.BuildIT.testClassLoaderLinkageError line 102 - More details - Source on GitHub

org.opentest4j.AssertionFailedError: 

expected: 0

@gsmet gsmet merged commit cd3ad1f into quarkusio:main Mar 2, 2023
@quarkus-bot quarkus-bot bot added this to the 3.0 - main milestone Mar 2, 2023
@Sgitario Sgitario deleted the 13969 branch March 2, 2023 12:17
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants