search

reactor / reactor-netty

TCP/HTTP/UDP/QUIC client/server with Reactor over Netty
https://projectreactor.io
Apache License 2.0
2.6k stars 645 forks source link

HttpClient using H2 protocol results in error when a response has header Content-Encoding:gzip #1379

Closed maddenj-ie closed 4 years ago

maddenj-ie commented 4 years ago

Original issue created on Spring Framework: https://github.com/spring-projects/spring-framework/issues/26056

maddenj-ie commented 4 years ago

I've created a basic application which only uses the HttpClient that I think also exhibits the behaviour .

        SslContext sslCtx = SslContextBuilder.forClient().sslProvider(SslProvider.JDK)
            .ciphers(Http2SecurityUtil.CIPHERS, SupportedCipherSuiteFilter.INSTANCE)
            .trustManager(InsecureTrustManagerFactory.INSTANCE)
            .applicationProtocolConfig(
                new ApplicationProtocolConfig(Protocol.ALPN, SelectorFailureBehavior.NO_ADVERTISE,
                    SelectedListenerFailureBehavior.ACCEPT, ApplicationProtocolNames.HTTP_2))
            .build();

        HttpClient client = HttpClient.create().compress(true).wiretap(true)
            .baseUrl("https://localhost:8443/nf-cicd-proto-service/v1")
            .protocol(HttpProtocol.H2)
            .secure(ssl -> ssl.sslContext(sslCtx));

        Tuple2<ByteBuf, HttpHeaders> response = client.get().uri("/test")
            .responseSingle((res, bytes) -> bytes.retain().zipWith(Mono.just(res.responseHeaders()))).block();

        LOGGER.info("Used stream ID: {}", response.getT2().get("x-http2-stream-id"));
        LOGGER.info("Response: {}", ByteBufUtil.prettyHexDump(response.getT1()));

With compression disabled

15:37:17.514 [main] INFO com.tango.reactorHttpClient.ReactorApplication - Used stream ID: 3
15:37:17.515 [main] INFO com.tango.reactorHttpClient.ReactorApplication - Response:          +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 7b 22 73 65 72 76 69 63 65 46 69 65 6c 64 22 3a |{"serviceField":|
|00000010| 22 73 65 72 76 69 63 65 46 69 65 6c 64 44 61 74 |"serviceFieldDat|
|00000020| 61 22 7d                                        |a"}             |
+--------+-------------------------------------------------+----------------+

With compression enabled

15:32:28.702 [main] INFO com.tango.reactorHttpClient.ReactorApplication - Used stream ID: 3
15:32:28.703 [main] INFO com.tango.reactorHttpClient.ReactorApplication - Response:          +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 1f 8b 08 00 00 00 00 00 00 00 aa 56 2a 4e 2d 2a |...........V*N-*|
|00000010| cb 4c 4e 75 cb 4c cd 49 51 b2 42 e1 ba 24 96 24 |.LNu.L.IQ.B..$.$|
|00000020| 2a d5 02 00 00 00 ff ff 03 00 1f 4a 71 98 23 00 |*..........Jq.#.|
|00000030| 00 00                                           |..              |
+--------+-------------------------------------------------+----------------+
violetagg commented 4 years ago

@maddenj-ie Will you be able to test #1381 ?

maddenj-ie commented 4 years ago

Hi @violetagg

Using my HttpClient app the output looks good to me.

10:14:39.778 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.Http2ConnectionProvider - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] Channel acquired from the parent pool, now 1 active connections and 0 inactive connections
10:14:39.778 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.Http2ConnectionProvider - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] Channel activated, now 1 active connections and 0 inactive connections
10:14:39.793 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClientOperations - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443](H2 - -1) New HTTP/2 stream
10:14:39.799 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClientConfig - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443](H2 - -1) Initialized HTTP/2 stream pipeline AbstractHttp2StreamChannel$3{(HttpClientConfig$H2Codec#0 = reactor.netty.http.client.HttpClientConfig$H2Codec), (reactor.left.h2ToHttp11Codec = io.netty.handler.codec.http2.Http2StreamFrameToHttpObjectCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.client.Http2StreamBridgeClientHandler), (reactor.left.httpDecompressor = io.netty.handler.codec.http.HttpContentDecompressor), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
10:14:39.801 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClientConnect - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443](H2 - -1) Handler is being applied: {uri=https://localhost:8443/nf-cicd-proto-service/v1/test, method=GET}
10:14:39.813 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.h2 - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] OUTBOUND HEADERS: streamId=3 headers=DefaultHttp2Headers[:path: /nf-cicd-proto-service/v1/test, :method: GET, :scheme: https, :authority: localhost:8443, accept-encoding: gzip, accept-encoding: gzip, user-agent: ReactorNetty/1.0.2-SNAPSHOT, accept: */*, content-length: 0] padding=0 endStream=true
10:14:39.818 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] WRITE: 9B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 5e 01 05 00 00 00 03                      |..^......       |
+--------+-------------------------------------------------+----------------+
10:14:39.819 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] WRITE: 94B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 44 1e 2f 6e 66 2d 63 69 63 64 2d 70 72 6f 74 6f |D./nf-cicd-proto|
|00000010| 2d 73 65 72 76 69 63 65 2f 76 31 2f 74 65 73 74 |-service/v1/test|
|00000020| 82 87 41 0e 6c 6f 63 61 6c 68 6f 73 74 3a 38 34 |..A.localhost:84|
|00000030| 34 33 50 04 67 7a 69 70 be 7a 1b 52 65 61 63 74 |43P.gzip.z.React|
|00000040| 6f 72 4e 65 74 74 79 2f 31 2e 30 2e 32 2d 53 4e |orNetty/1.0.2-SN|
|00000050| 41 50 53 48 4f 54 53 03 2a 2f 2a 5c 01 30       |APSHOTS.*/*\.0  |
+--------+-------------------------------------------------+----------------+
10:14:39.821 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.Http2ConnectionProvider - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443](H2 - 3) Stream opened, now 1 active streams, 100 max active streams.
10:14:39.824 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.Http2ConnectionProvider - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] Channel deactivated, now 0 active connections and 1 inactive connections
10:14:39.825 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] 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                      |.........       |
+--------+-------------------------------------------------+----------------+
10:14:39.825 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.h2 - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] INBOUND SETTINGS: ack=true
10:14:39.826 [reactor-http-epoll-2] DEBUG io.netty.channel.DefaultChannelPipeline - Discarded inbound message DefaultHttp2SettingsAckFrame that reached at the tail of the pipeline. Please check your pipeline configuration.
10:14:39.826 [reactor-http-epoll-2] DEBUG io.netty.channel.DefaultChannelPipeline - Discarded message pipeline : [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, reactor.left.h2MultiplexHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443].
10:14:39.826 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] READ: 17B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 08 06 00 00 00 00 00 00 00 00 00 00 00 00 |................|
|00000010| 01                                              |.               |
+--------+-------------------------------------------------+----------------+
10:14:39.826 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.h2 - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] INBOUND PING: ack=false bytes=1
10:14:39.827 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.h2 - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] OUTBOUND PING: ack=true bytes=1
10:14:39.827 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] WRITE: 17B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 08 06 01 00 00 00 00 00 00 00 00 00 00 00 |................|
|00000010| 01                                              |.               |
+--------+-------------------------------------------------+----------------+
10:14:39.827 [reactor-http-epoll-2] DEBUG io.netty.channel.DefaultChannelPipeline - Discarded inbound message DefaultHttp2PingFrame(content=1, ack=false) that reached at the tail of the pipeline. Please check your pipeline configuration.
10:14:39.828 [reactor-http-epoll-2] DEBUG io.netty.channel.DefaultChannelPipeline - Discarded message pipeline : [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, reactor.left.h2MultiplexHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443].
10:14:39.828 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] READ COMPLETE
10:14:39.828 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] FLUSH
10:14:39.834 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] READ: 70B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 3d 01 04 00 00 00 03 3f e1 1f 88 7b 8b 19 |..=......?...{..|
|00000010| 08 5a d2 b1 6a 21 e4 35 53 7f 5a 04 67 7a 69 70 |.Z..j!.5S.Z.gzip|
|00000020| 5f 8b 1d 75 d0 62 0d 26 3d 4c 74 41 ea 1f 12 96 |_..u.b.&=LtA....|
|00000030| c3 61 be 94 0b 2a 69 3f 75 04 01 01 40 82 e0 5a |.a...*i?u...@..Z|
|00000040| b8 cb ea 62 d1 bf                               |...b..          |
+--------+-------------------------------------------------+----------------+
10:14:39.836 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.h2 - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] INBOUND HEADERS: streamId=3 headers=DefaultHttp2Headers[:status: 200, vary: accept-encoding, content-encoding: gzip, content-type: application/json, date: Fri, 13 Nov 2020 10:14:39 GMT] padding=0 endStream=false
10:14:39.845 [reactor-http-epoll-2] DEBUG io.netty.handler.codec.compression.ZlibCodecFactory - -Dio.netty.noJdkZlibDecoder: false
10:14:39.845 [reactor-http-epoll-2] DEBUG io.netty.handler.codec.compression.ZlibCodecFactory - -Dio.netty.noJdkZlibEncoder: false
10:14:39.852 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClientOperations - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443](H2 - 3) Received response (auto-read:false) : [vary=accept-encoding, content-type=application/json, date=Fri, 13 Nov 2020 10:14:39 GMT, x-http2-stream-id=3, transfer-encoding=chunked]
10:14:39.868 [reactor-http-epoll-2] DEBUG reactor.netty.channel.FluxReceive - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443](H2 - 3) FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver
10:14:39.870 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] READ COMPLETE
10:14:39.870 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] FLUSH
10:14:39.870 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] FLUSH
10:14:39.871 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] READ: 49B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 28 00 00 00 00 00 03 1f 8b 08 00 00 00 00 |..(.............|
|00000010| 00 00 00 aa 56 2a 4e 2d 2a cb 4c 4e 75 cb 4c cd |....V*N-*.LNu.L.|
|00000020| 49 51 b2 42 e1 ba 24 96 24 2a d5 02 00 00 00 ff |IQ.B..$.$*......|
|00000030| ff                                              |.               |
+--------+-------------------------------------------------+----------------+
10:14:39.871 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.h2 - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] INBOUND DATA: streamId=3 padding=0 endStream=false length=40 bytes=1f8b0800000000000000aa562a4e2d2acb4c4e75cb4ccd4951b242e1ba2496242ad502000000ffff
10:14:39.874 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] READ: 19B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 0a 00 01 00 00 00 03 03 00 1f 4a 71 98 23 |............Jq.#|
|00000010| 00 00 00                                        |...             |
+--------+-------------------------------------------------+----------------+
10:14:39.874 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.h2 - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] INBOUND DATA: streamId=3 padding=0 endStream=true length=10 bytes=03001f4a719823000000
10:14:39.877 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClientOperations - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443](H2 - 3) Received last HTTP packet
10:14:39.878 [main] INFO com.tango.reactorHttpClient.ReactorApplication - Used stream ID: 3
10:14:39.878 [main] INFO com.tango.reactorHttpClient.ReactorApplication - Response:          +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 7b 22 73 65 72 76 69 63 65 46 69 65 6c 64 22 3a |{"serviceField":|
|00000010| 22 73 65 72 76 69 63 65 46 69 65 6c 64 44 61 74 |"serviceFieldDat|
|00000020| 61 22 7d                                        |a"}             |
+--------+-------------------------------------------------+----------------+
10:14:39.879 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.Http2ConnectionProvider - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443](H2 - 3) Stream closed, now 0 active streams, 100 max active streams.
10:14:39.879 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClient - [id: 0x901219f0, L:/127.0.0.1:35642 - R:localhost/127.0.0.1:8443] READ COMPLETE

I've also tested the SNAPSHOT using my original Spring Boot applications and the error is no longer present.

Thanks for fixing so quickly.

violetagg commented 4 years ago

@maddenj-ie Thanks for testing it!