HTTP/1.1 is being logged and recorded by metrics even though HTTP/2 is enabled

Question

HTTP/1.1 is being logged and recorded by metrics even though HTTP/2 is enabled

miriyusifli opened this issue 7 months ago · 10 comments

Context

Hi, I have enabled HTTP/2 on the server side and client side. Whenever I send a request using the curl command I am getting the following response as expected. Some configuration-related details:

No SSL
Server uses Jetty
Both H2C and HTTP/1.1 are enabled on the server

HTTP/1.1 101 Switching Protocols

HTTP/2 204
date: Mon, 04 Mar 2024 20:12:20 GMT
x-content-type-options: nosniff
x-xss-protection: 1; mode=block
cache-control: no-cache, no-store, max-age=0, must-revalidate
pragma: no-cache
expires: 0
x-frame-options: DENY

Problem

However, every time I send a request from the client application to the server, it records certain HTTP/1.1 logs that I don't understand, despite observing only HTTP/2 requests in Wireshark. Below is the logged HTTP/1.1 related logs.

HTTP/1.1 204 No Content
date: <filtered>
x-content-type-options: <filtered>
x-xss-protection: <filtered>
cache-control: <filtered>
pragma: <filtered>
expires: <filtered>
x-frame-options: <filtered>
content-length: <filtered>
x-http2-stream-id: <filtered>

A response status of 204 is an expected status code according to our business requirements. Additionally, it's worth noting that Netty metrics capture certain HTTP/1.1 calls. Specifically, I'm utilizing the reactor.netty.connection.provider.active.connections metric. However, I'm confused by the presence of two distinct connection providers: one labeled http2.http.client and the other labeled http.client. In the application I only have http.client

Here is the full log regarding a call from the client to the server.

2024-03-04 20:09:59.902 DEBUG [] 64006 --- [ctor-http-nio-4] r.n.http.server.HttpServerOperations     : [c075df81, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60429] Increasing pending responses, now 1
2024-03-04 20:09:59.903 DEBUG [] 64006 --- [ctor-http-nio-4] reactor.netty.http.server.HttpServer     : [c075df81-4, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60429] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@1d46b6ad
2024-03-04 20:09:59.908 DEBUG [] 64006 --- [ctor-http-nio-4] reactor.netty.channel.FluxReceive        : [c075df81-4, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60429] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver
2024-03-04 20:09:59.924 DEBUG [] 64006 --- [ctor-http-nio-4] reactor.netty.http.client.Http2Pool      : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] Channel activated
2024-03-04 20:09:59.926 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.Http2Pool      : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] Channel deactivated
2024-03-04 20:09:59.926 DEBUG [] 64006 --- [ds.client-nio-3] r.n.http.client.HttpClientOperations     : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090](H2 - -1) New HTTP/2 stream
2024-03-04 20:09:59.926 DEBUG [] 64006 --- [ds.client-nio-3] r.netty.http.client.HttpClientConfig     : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090](H2 - -1) Initialized HTTP/2 stream pipeline AbstractHttp2StreamChannel$3{(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.left.httpMetricsHandler = reactor.netty.http.client.HttpClientMetricsHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2024-03-04 20:09:59.926 DEBUG [] 64006 --- [ds.client-nio-3] r.netty.http.client.HttpClientConnect    : [0df061c4/2-1, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] Handler is being applied: {uri=http://localhost:9090/events, method=GET}
2024-03-04 20:09:59.927 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.h2             : [id: 0x0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] OUTBOUND HEADERS: streamId=5 headers=DefaultHttp2Headers[:path: /events, :scheme: http, :authority: localhost:9090, :method: GET, user-agent: ReactorNetty/1.0.39, accept: application/octet-stream, accept-encoding: gzip, x-b3-traceid: e6d3e30dace59ac8, x-b3-spanid: 4b42594751ecd447, x-b3-parentspanid: e6d3e30dace59ac8, x-b3-sampled: 1] padding=0 endStream=false
2024-03-04 20:09:59.931 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.HttpClient     : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] WRITE: 9B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 41 01 04 00 00 00 05                      |..A......       |
+--------+-------------------------------------------------+----------------+
2024-03-04 20:09:59.931 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.HttpClient     : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] WRITE: 65B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| c6 86 c5 82 c4 c3 c2 7f 02 10 65 36 64 33 65 33 |..........e6d3e3|
|00000010| 30 64 61 63 65 35 39 61 63 38 7f 02 10 34 62 34 |0dace59ac8...4b4|
|00000020| 32 35 39 34 37 35 31 65 63 64 34 34 37 7f 02 10 |2594751ecd447...|
|00000030| 65 36 64 33 65 33 30 64 61 63 65 35 39 61 63 38 |e6d3e30dace59ac8|
|00000040| c1                                              |.               |
+--------+-------------------------------------------------+----------------+
2024-03-04 20:09:59.931 DEBUG [] 64006 --- [ds.client-nio-3] r.n.http.client.Http2ConnectionProvider  : [0df061c4/2-1, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] Stream opened, now: 1 active streams and 255 max active streams.
2024-03-04 20:09:59.931 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.HttpClient     : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] FLUSH
2024-03-04 20:09:59.931 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.h2             : [id: 0x0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] OUTBOUND DATA: streamId=5 padding=0 endStream=true length=0 bytes=
2024-03-04 20:09:59.931 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.HttpClient     : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] 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 05                      |.........       |
+--------+-------------------------------------------------+----------------+
2024-03-04 20:09:59.931 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.HttpClient     : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] WRITE: 0B
2024-03-04 20:09:59.932 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.HttpClient     : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] FLUSH
2024-03-04 20:09:59.994 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.HttpClient     : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] READ: 41B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 20 01 05 00 00 00 05 89 61 96 d0 7a be 94 |.. .......a..z..|
|00000010| 03 4a 68 1d 8a 08 02 69 40 bf 70 0f dc 6d f5 31 |.Jh....i@.p..m.1|
|00000020| 68 df c5 c4 c3 c2 c1 c0 bf                      |h........       |
+--------+-------------------------------------------------+----------------+
2024-03-04 20:09:59.994 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.h2             : [id: 0x0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] INBOUND HEADERS: streamId=5 headers=DefaultHttp2Headers[:status: 204, date: Mon, 04 Mar 2024 19:09:59 GMT, x-content-type-options: nosniff, x-xss-protection: 1; mode=block, cache-control: no-cache, no-store, max-age=0, must-revalidate, pragma: no-cache, expires: 0, x-frame-options: DENY, content-length: 0] padding=0 endStream=true
2024-03-04 20:09:59.995 DEBUG [] 64006 --- [ds.client-nio-3] r.n.http.client.HttpClientOperations     : [0df061c4/2-1, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] Received response (auto-read:false) : FULL_RESPONSE(decodeResult: success, version: HTTP/1.1, content: PooledUnsafeDirectByteBuf(ridx: 0, widx: 0, cap: 256))
HTTP/1.1 204 No Content
date: <filtered>
x-content-type-options: <filtered>
x-xss-protection: <filtered>
cache-control: <filtered>
pragma: <filtered>
expires: <filtered>
x-frame-options: <filtered>
content-length: <filtered>
x-http2-stream-id: <filtered>
2024-03-04 20:09:59.996 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.channel.FluxReceive        : [0df061c4/2-1, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver
2024-03-04 20:10:00.002 DEBUG [] 64006 --- [ctor-http-nio-4] r.n.http.server.HttpServerOperations     : [c075df81-4, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60429] Decreasing pending responses, now 0
2024-03-04 20:10:00.002 DEBUG [] 64006 --- [ds.client-nio-3] r.n.http.client.Http2ConnectionProvider  : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090](H2 - 5) Stream closed, now: 0 active streams and 255 max active streams.
2024-03-04 20:10:00.003 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.HttpClient     : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] READ COMPLETE
2024-03-04 20:10:00.003 DEBUG [] 64006 --- [ds.client-nio-3] reactor.netty.http.client.HttpClient     : [0df061c4, L:/127.0.0.1:50750 - R:localhost/127.0.0.1:9090] FLUSH
2024-03-04 20:10:00.004 DEBUG [] 64006 --- [ctor-http-nio-4] r.n.http.server.HttpServerOperations     : [c075df81-4, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60429] Last HTTP response frame
2024-03-04 20:10:00.004 DEBUG [] 64006 --- [ctor-http-nio-4] reactor.netty.channel.ChannelOperations  : [c075df81-4, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60429] [HttpServer] Channel inbound receiver cancelled (subscription disposed).
2024-03-04 20:10:00.004 DEBUG [] 64006 --- [ctor-http-nio-4] r.n.http.server.HttpServerOperations     : [c075df81-4, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60429] Last HTTP packet was sent, terminating the channel

How I configured HTTP/2?

HttpClient httpClient = httpClient(
                HttpClient.create(reactorResourceFactory.getConnectionProvider()), properties, resourceFactory(properties).getLoopResources());


private ReactorResourceFactory resourceFactory(WebClientProperties properties) {
        final ReactorResourceFactory factory = new ReactorResourceFactory();
        factory.setUseGlobalResources(false);
        factory.setConnectionProvider(ConnectionProvider
                .builder(properties.getEventLoopName())
                .maxConnections(properties.getMaxConnection())
                .pendingAcquireMaxCount(properties.getPendingAcquireQueueMaxCount())
                .maxIdleTime(Duration.ofMillis(properties.getMaxIdleTime()))
                .pendingAcquireTimeout(Duration.ofMillis(properties.getAcquireTimeout())).build());
        factory.setLoopResources(LoopResources.create(properties.getEventLoopName(), properties.getWorkers(), properties.isDaemon()));

        return factory;
        
        
  private HttpClient httpClient(HttpClient client, WebClientProperties properties, LoopResources loopResources) {
  return client
                .compress(true)
                .protocol(HttpProtocol.H2C)
                .wiretap(true)
                .metrics(true, Function.identity())
                .runOn(loopResources)
                .option(CONNECT_TIMEOUT_MILLIS, properties.getConnectionTimeout())
                .option(TCP_NODELAY, true)
                .doOnConnected(conn -> {
                    if (properties.getReadTimeout() != null) {
                        conn.addHandlerLast(new ReadTimeoutHandler(properties.getReadTimeout()));
                    }
                    if (properties.getWriteTimeout() != null) {
                        conn.addHandlerLast(new WriteTimeoutHandler(properties.getWriteTimeout()));
                    }
                    if (properties.isEnableLog()) {
                        conn.addHandlerLast(new LoggingHandler(LogLevel.DEBUG));
                    }
                });
    }

Question

Are there any misconfigurations? I'm confused by the appearance of HTTP/1.1 entries in logs and metrics, despite Wireshark exclusively displaying HTTP/2 calls.

Answer 1 · 2024-03-05T08:15:31.000Z

@miriyusifli

HTTP/1.1 204 No Content
date: <filtered>
x-content-type-options: <filtered>
x-xss-protection: <filtered>
cache-control: <filtered>
pragma: <filtered>
expires: <filtered>
x-frame-options: <filtered>
content-length: <filtered>
x-http2-stream-id: <filtered>

This is an internal implementation detail. At some point Reactor Netty uses for HTTP/2 the same implementation as HTTP/1.1,
because of that you see this log. However you can also see that there definitely a header with stream id is presented, something that you cannot see with HTTP/1.1 request.

I'm confused by the presence of two distinct connection providers: one labeled http2.http.client and the other labeled http.client.

This is also an internal implementation detail. For HTTP/2 we track the connections and the streams.

Answer 2 · 2024-03-05T08:25:53.000Z

Thanks for the quick reply @violetagg.

My interest is knowing the number of HTTP connections within the application and its impact on performance. Thus, I am interested in HTTP connections maintained by the application. Should I ignore the recorded HTTP/1.1 (http.client) calls in the metrics and concentrate only on (http2.http.client)?

I would like to know more info about usage of HTTP/1.1 calls recorded by the metric.

Answer 3 · 2024-03-05T08:36:00.000Z

Thanks for the quick reply @violetagg.

My interest is knowing the number of HTTP connections within the application and its impact on performance. Thus, I am interested in HTTP connections maintained by the application. Should I ignore the recorded HTTP/1.1 (http.client) calls in the metrics and concentrate only on (http2.http.client)?

With http2.http.client you should be able to track:

active connections
idle connections
pending acquire streams
active streams

I would like to know more info about usage of HTTP/1.1 calls recorded by the metric.

Answer 4 · 2024-03-05T11:00:42.000Z

The metrics are confusing. E.g:

How is it possible that active connections don't show any HTTP/2 calls even though the application only uses HTTP/2? As you can see Idle connections graph is showing some idle HTTP/2 connections. How a connection can idle without being active?
I have max 20 seconds idle time but according to metrics connections are in the idle state even after 20 seconds.

Answer 5 · 2024-03-05T12:01:18.000Z

well we make difference between connections and streams: active connection means that we take this connection in order to open a stream, once the stream is opened, the connection is returned to the pool and is idle until we need to open a new stream. So is it possible to add to this graph also the active streams?

Answer 6 · 2024-03-05T12:20:04.000Z

@violetagg
Here it is

Does it use HTTP/1.1 connection to open the stream? Trying to understand why I see HTTP/1.1 connections in graph, but not HTTP/2 connections

Answer 7 · 2024-03-05T13:04:04.000Z

Yes HTTP/2 pool uses HTTP/1.1 pool for establishing connections to the remote.

Answer 8 · 2024-03-05T14:22:39.000Z

@violetagg

My assumption is that it uses HTTP/1.1 to create streams and then uses streams for communication. Therefore, there is no any HTTP/2 connections recorded on the active connections graph. But interestingly it is showing HTTP/2 connections on the idle connections graph.
Can a stream be used again and again for different requests?

Answer 9 · 2024-03-05T14:52:50.000Z

@miriyusifli Here is how it is implemented (simplified view):
Request comes to HTTP/2 pool - a connection is established via HTTP/1.1 pool and stays in HTTP/1.1 pool as active, however in HTTP/2 pool this connection will be marked as active only when a stream creation is needed (this should be pretty quick operation) and will stay idle if for the moment there is no need to create streams.
Streams are never reused.

Answer 10 · 2024-03-06T15:52:26.000Z

@miriyusifli I'm closing this as IMO Reactor Netty works as expected. For any further questions please ask on Gitter or Stack Overflow.