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

reactor_netty_http_server_connections_total with negative values #2956

Closed
violetagg opened this issue Nov 2, 2023 · 3 comments · Fixed by #2958
Closed

reactor_netty_http_server_connections_total with negative values #2956

violetagg opened this issue Nov 2, 2023 · 3 comments · Fixed by #2958
Assignees
@violetagg
Labels
type/bug A general bug
Milestone
1.0.39

Comments

@violetagg
Copy link
Member

violetagg commented Nov 2, 2023 •
edited
Loading

Thanks,

I still see that total metrics is not working correctly, luckily I was able to "repro it".
Issue seems to happen with standard metrics too

	@Override
	public void customize(NettyReactiveWebServerFactory factory) {
		factory.addServerCustomizers(server -> server.metrics(true,uri -> uri  ));
	}

reactor_netty_http_server_connections_total{local_address="127.0.0.1:8081",uri="http",} -22.0
reactor_netty_http_server_connections_total{local_address="0:0:0:0:0:0:0:1:8081",uri="http",} -22.0

{
"name": "reactor.netty.http.server.connections.total",
"measurements": [
{
"statistic": "VALUE",
"value": -44
}
],
"availableTags": [
{
"tag": "uri",
"values": [
"http"
]
},
{
"tag": "local.address",
"values": [
"127.0.0.1:8081",
"0:0:0:0:0:0:0:1:8081"
]
}
]
}

I enabled all netty logs logging.level.reactor.netty=TRACE and noticed that someone tried to open non-TLS connection to TLS port. Turn out that I had browser window opened which tried to open Prometheus endpoint without TLS.
But same can be triggered by calling actuator endpoint without TLS.

I added logging to recordTlsHandshakeTime/recordServerConnectionOpened/recordServerConnectionClosed/recordServerConnectionActive/recordServerConnectionInactive.

When TLS fails it can be seen that Opened is not called at all but Closed is called.

2023-11-02T11:44:53.628+02:00 DEBUG 11588 --- [ctor-http-nio-5] reactor.netty.tcp.SslProvider            : [abd66895, L:/[0:0:0:0:0:0:0:1]:8081 - R:/[0:0:0:0:0:0:0:1]:49537] SSL enabled using engine SSLEngine[hostname=null, port=-1, Session(1698918293627|SSL_NULL_WITH_NULL_NULL)]
2023-11-02T11:44:53.628+02:00 DEBUG 11588 --- [ctor-http-nio-5] r.n.http.server.HttpServerOperations     : [abd66895, L:/[0:0:0:0:0:0:0:1]:8081 - R:/[0:0:0:0:0:0:0:1]:49537] New http connection, requesting read
2023-11-02T11:44:53.629+02:00 DEBUG 11588 --- [ctor-http-nio-5] r.netty.transport.TransportConfig        : [abd66895, L:/[0:0:0:0:0:0:0:1]:8081 - R:/[0:0:0:0:0:0:0:1]:49537] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (reactor.left.channelMetricsHandler = reactor.netty.channel.ChannelMetricsHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.left.httpMetricsHandler = reactor.netty.http.server.HttpServerMetricsHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2023-11-02T11:44:53.630+02:00  INFO 11588 --- [ctor-http-nio-5] ustomMicrometerHttpServerMetricsRecorder : TLSStart /[0:0:0:0:0:0:0:1]:49537 ERROR

2023-11-02T11:44:53.631+02:00  INFO 11588 --- [ctor-http-nio-5] ustomMicrometerHttpServerMetricsRecorder : TLSEnd /[0:0:0:0:0:0:0:1]:49537 ERROR 1

2023-11-02T11:44:53.631+02:00 DEBUG 11588 --- [ctor-http-nio-5] r.netty.transport.ServerTransport        : [abd66895, L:/[0:0:0:0:0:0:0:1]:8081 - R:/[0:0:0:0:0:0:0:1]:49537] onUncaughtException(SimpleConnection{channel=[id: 0xabd66895, L:/[0:0:0:0:0:0:0:1]:8081 - R:/[0:0:0:0:0:0:0:1]:49537]})

io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: 474554202f6d782f73746174757320485454502f312e310d0a486f73743a206c6f63616c686f73743a383038310d0a436f6e6e656374696f6e3a206b6565702d616c6976650d0a43616368652d436f6e74726f6c3a206d61782d6167653d300d0a7365632d63682d75613a20224368726f6d69756d223b763d22313138222c2022476f6f676c65204368726f6d65223b763d22313138222c20224e6f743d413f4272616e64223b763d223939220d0a7365632d63682d75612d6d6f62696c653a203f300d0a7365632d63682d75612d706c6174666f726d3a202257696e646f7773220d0a557067726164652d496e7365637572652d52657175657374733a20310d0a557365722d4167656e743a204d6f7a696c6c612f352e30202857696e646f7773204e542031302e303b2057696e36343b2078363429204170706c655765624b69742f3533372e333620284b48544d4c2c206c696b65204765636b6f29204368726f6d652f3131382e302e302e30205361666172692f3533372e33360d0a4163636570743a20746578742f68746d6c2c6170706c69636174696f6e2f7868746d6c2b786d6c2c6170706c69636174696f6e2f786d6c3b713d302e392c696d6167652f617669662c696d6167652f776562702c696d6167652f61706e672c2a2f2a3b713d302e382c6170706c69636174696f6e2f7369676e65642d65786368616e67653b763d62333b713d302e370d0a5365632d46657463682d536974653a206e6f6e650d0a5365632d46657463682d4d6f64653a206e617669676174650d0a5365632d46657463682d557365723a203f310d0a5365632d46657463682d446573743a20646f63756d656e740d0a4163636570742d456e636f64696e673a20677a69702c206465666c6174652c2062720d0a4163636570742d4c616e67756167653a20656e2d55532c656e3b713d302e390d0a436f6f6b69653a2067726166616e615f73657373696f6e3d66333437316264363761663334313061306133353961616139336237356338643b2067726166616e615f73657373696f6e5f6578706972793d313639383736333036370d0a0d0a
	at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1313) ~[netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1383) ~[netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529) ~[netty-codec-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468) ~[netty-codec-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) ~[netty-codec-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]

2023-11-02T11:44:53.632+02:00 DEBUG 11588 --- [ctor-http-nio-5] r.netty.transport.ServerTransport        : [abd66895, L:/[0:0:0:0:0:0:0:1]:8081 ! R:/[0:0:0:0:0:0:0:1]:49537] onUncaughtException(SimpleConnection{channel=[id: 0xabd66895, L:/[0:0:0:0:0:0:0:1]:8081 ! R:/[0:0:0:0:0:0:0:1]:49537]})

io.netty.handler.codec.DecoderException: io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: 474554202f6d782f73746174757320485454502f312e310d0a486f73743a206c6f63616c686f73743a383038310d0a436f6e6e656374696f6e3a206b6565702d616c6976650d0a43616368652d436f6e74726f6c3a206d61782d6167653d300d0a7365632d63682d75613a20224368726f6d69756d223b763d22313138222c2022476f6f676c65204368726f6d65223b763d22313138222c20224e6f743d413f4272616e64223b763d223939220d0a7365632d63682d75612d6d6f62696c653a203f300d0a7365632d63682d75612d706c6174666f726d3a202257696e646f7773220d0a557067726164652d496e7365637572652d52657175657374733a20310d0a557365722d4167656e743a204d6f7a696c6c612f352e30202857696e646f7773204e542031302e303b2057696e36343b2078363429204170706c655765624b69742f3533372e333620284b48544d4c2c206c696b65204765636b6f29204368726f6d652f3131382e302e302e30205361666172692f3533372e33360d0a4163636570743a20746578742f68746d6c2c6170706c69636174696f6e2f7868746d6c2b786d6c2c6170706c69636174696f6e2f786d6c3b713d302e392c696d6167652f617669662c696d6167652f776562702c696d6167652f61706e672c2a2f2a3b713d302e382c6170706c69636174696f6e2f7369676e65642d65786368616e67653b763d62333b713d302e370d0a5365632d46657463682d536974653a206e6f6e650d0a5365632d46657463682d4d6f64653a206e617669676174650d0a5365632d46657463682d557365723a203f310d0a5365632d46657463682d446573743a20646f63756d656e740d0a4163636570742d456e636f64696e673a20677a69702c206465666c6174652c2062720d0a4163636570742d4c616e67756167653a20656e2d55532c656e3b713d302e390d0a436f6f6b69653a2067726166616e615f73657373696f6e3d66333437316264363761663334313061306133353961616139336237356338643b2067726166616e615f73657373696f6e5f6578706972793d313639383736333036370d0a0d0a
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:499) ~[netty-codec-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) ~[netty-codec-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
Caused by: io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: 474554202f6d782f73746174757320485454502f312e310d0a486f73743a206c6f63616c686f73743a383038310d0a436f6e6e656374696f6e3a206b6565702d616c6976650d0a43616368652d436f6e74726f6c3a206d61782d6167653d300d0a7365632d63682d75613a20224368726f6d69756d223b763d22313138222c2022476f6f676c65204368726f6d65223b763d22313138222c20224e6f743d413f4272616e64223b763d223939220d0a7365632d63682d75612d6d6f62696c653a203f300d0a7365632d63682d75612d706c6174666f726d3a202257696e646f7773220d0a557067726164652d496e7365637572652d52657175657374733a20310d0a557365722d4167656e743a204d6f7a696c6c612f352e30202857696e646f7773204e542031302e303b2057696e36343b2078363429204170706c655765624b69742f3533372e333620284b48544d4c2c206c696b65204765636b6f29204368726f6d652f3131382e302e302e30205361666172692f3533372e33360d0a4163636570743a20746578742f68746d6c2c6170706c69636174696f6e2f7868746d6c2b786d6c2c6170706c69636174696f6e2f786d6c3b713d302e392c696d6167652f617669662c696d6167652f776562702c696d6167652f61706e672c2a2f2a3b713d302e382c6170706c69636174696f6e2f7369676e65642d65786368616e67653b763d62333b713d302e370d0a5365632d46657463682d536974653a206e6f6e650d0a5365632d46657463682d4d6f64653a206e617669676174650d0a5365632d46657463682d557365723a203f310d0a5365632d46657463682d446573743a20646f63756d656e740d0a4163636570742d456e636f64696e673a20677a69702c206465666c6174652c2062720d0a4163636570742d4c616e67756167653a20656e2d55532c656e3b713d302e390d0a436f6f6b69653a2067726166616e615f73657373696f6e3d66333437316264363761663334313061306133353961616139336237356338643b2067726166616e615f73657373696f6e5f6578706972793d313639383736333036370d0a0d0a
	at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1313) ~[netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1383) ~[netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529) ~[netty-codec-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468) ~[netty-codec-4.1.100.Final.jar:4.1.100.Final]
	... 17 common frames omitted

2023-11-02T11:44:53.633+02:00  INFO 11588 --- [ctor-http-nio-5] ustomMicrometerHttpServerMetricsRecorder : TotalClosedBefore -1 /[0:0:0:0:0:0:0:1]:8081

2023-11-02T11:44:53.633+02:00  INFO 11588 --- [ctor-http-nio-5] ustomMicrometerHttpServerMetricsRecorder : TotalClosedAfter -2 /[0:0:0:0:0:0:0:1]:8081

In success case it can be seen that Opened is called after TLS successful only.
Maybe Opened should be called before TLS already.

In success case also active is increased after TLS, maybe should be also called "before" TLS

2023-11-02T11:44:34.402+02:00 DEBUG 11588 --- [ctor-http-nio-3] reactor.netty.tcp.SslProvider            : [a0d40952, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] SSL enabled using engine SSLEngine[hostname=null, port=-1, Session(1698918274399|SSL_NULL_WITH_NULL_NULL)]
2023-11-02T11:44:34.425+02:00 DEBUG 11588 --- [ctor-http-nio-3] r.n.http.server.HttpServerOperations     : [a0d40952, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] New http connection, requesting read
2023-11-02T11:44:34.427+02:00 DEBUG 11588 --- [ctor-http-nio-3] r.netty.transport.TransportConfig        : [a0d40952, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (reactor.left.channelMetricsHandler = reactor.netty.channel.ChannelMetricsHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.left.httpMetricsHandler = reactor.netty.http.server.HttpServerMetricsHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2023-11-02T11:44:34.496+02:00  INFO 11588 --- [ctor-http-nio-3] ustomMicrometerHttpServerMetricsRecorder : TLSStart /127.0.0.1:48799 SUCCESS

2023-11-02T11:44:34.503+02:00  INFO 11588 --- [ctor-http-nio-3] ustomMicrometerHttpServerMetricsRecorder : TLSEnd /127.0.0.1:48799 SUCCESS 1

2023-11-02T11:44:34.504+02:00  INFO 11588 --- [ctor-http-nio-3] ustomMicrometerHttpServerMetricsRecorder : TotalOpenedBefore 0 /127.0.0.1:8081

2023-11-02T11:44:34.504+02:00  INFO 11588 --- [ctor-http-nio-3] ustomMicrometerHttpServerMetricsRecorder : TotalOpenedAfter 1 /127.0.0.1:8081

2023-11-02T11:44:34.509+02:00 DEBUG 11588 --- [ctor-http-nio-3] r.n.http.server.HttpServerOperations     : [a0d40952, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] Increasing pending responses, now 1
2023-11-02T11:44:34.519+02:00  INFO 11588 --- [ctor-http-nio-3] ustomMicrometerHttpServerMetricsRecorder : ActiveBefore 0 /127.0.0.1:8081

2023-11-02T11:44:34.519+02:00  INFO 11588 --- [ctor-http-nio-3] ustomMicrometerHttpServerMetricsRecorder : ActiveAfter 1 /127.0.0.1:8081

2023-11-02T11:44:34.520+02:00 DEBUG 11588 --- [ctor-http-nio-3] reactor.netty.http.server.HttpServer     : [a0d40952-1, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@72ddbede
2023-11-02T11:44:34.565+02:00  INFO 11588 --- [ctor-http-nio-3] reactor.Mono.Just.1                      : | onSubscribe([Synchronous Fuseable] Operators.ScalarSubscription)
2023-11-02T11:44:34.566+02:00  INFO 11588 --- [ctor-http-nio-3] reactor.Mono.Just.1                      : | request(unbounded)
2023-11-02T11:44:34.566+02:00  INFO 11588 --- [ctor-http-nio-3] reactor.Mono.Just.1                      : | onNext(monoCancel)
2023-11-02T11:44:34.570+02:00  INFO 11588 --- [ctor-http-nio-3] reactor.Mono.Just.1                      : | onComplete()
2023-11-02T11:44:34.576+02:00 DEBUG 11588 --- [ctor-http-nio-3] r.n.http.server.HttpServerOperations     : [a0d40952-1, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] Decreasing pending responses, now 0
2023-11-02T11:44:34.587+02:00  INFO 11588 --- [ctor-http-nio-3] ustomMicrometerHttpServerMetricsRecorder : InactiveBefore 1 /127.0.0.1:8081

2023-11-02T11:44:34.587+02:00  INFO 11588 --- [ctor-http-nio-3] ustomMicrometerHttpServerMetricsRecorder : InActiveAfter 0 /127.0.0.1:8081

2023-11-02T11:44:34.587+02:00 DEBUG 11588 --- [ctor-http-nio-3] r.n.http.server.HttpServerOperations     : [a0d40952-1, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] Last HTTP packet was sent, terminating the channel
2023-11-02T11:44:34.588+02:00 DEBUG 11588 --- [ctor-http-nio-3] r.netty.channel.ChannelOperations        : [a0d40952-1, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] [HttpServer] Channel inbound receiver cancelled (operation cancelled).
2023-11-02T11:44:34.590+02:00 DEBUG 11588 --- [ctor-http-nio-3] r.n.http.server.HttpServerOperations     : [a0d40952-1, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] Last HTTP response frame
2023-11-02T11:44:34.597+02:00 DEBUG 11588 --- [ctor-http-nio-3] reactor.netty.channel.FluxReceive        : [a0d40952-1, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] [terminated=false, cancelled=true, pending=0, error=null]: dropping frame LAST_CONTENT(decodeResult: success, content: PooledSlicedByteBuf(ridx: 0, widx: 1, cap: 1/1, unwrapped: PooledUnsafeDirectByteBuf(ridx: 380, widx: 380, cap: 418)))
2023-11-02T11:44:34.598+02:00 DEBUG 11588 --- [ctor-http-nio-3] reactor.netty.ReactorNetty               : [a0d40952-1, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] Non Removed handler: reactor.left.readTimeoutHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.channelMetricsHandler = reactor.netty.channel.ChannelMetricsHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.left.httpMetricsHandler = reactor.netty.http.server.HttpServerMetricsHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2023-11-02T11:44:34.598+02:00 TRACE 11588 --- [ctor-http-nio-3] r.netty.channel.ChannelOperations        : [a0d40952, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] Disposing ChannelOperation from a channel

java.lang.Exception: ChannelOperation terminal stack
	at reactor.netty.channel.ChannelOperations.terminate(ChannelOperations.java:490) ~[reactor-netty-core-1.1.12.jar:1.1.12]
	at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:566) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.100.Final.jar:4.1.100.Final]
	at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]

2023-11-02T11:44:34.602+02:00 DEBUG 11588 --- [ctor-http-nio-3] r.n.channel.ChannelOperationsHandler     : [a0d40952, L:/127.0.0.1:8081 - R:/127.0.0.1:48799] Received a TLS close_notify, closing the channel now.
2023-11-02T11:44:34.604+02:00  INFO 11588 --- [ctor-http-nio-3] ustomMicrometerHttpServerMetricsRecorder : TotalClosedBefore 1 /127.0.0.1:8081

2023-11-02T11:44:34.605+02:00  INFO 11588 --- [ctor-http-nio-3] ustomMicrometerHttpServerMetricsRecorder : TotalClosedAfter 0 /127.0.0.1:8081

Originally posted by @jtorkkel in #2940 (comment)
@violetagg violetagg mentioned this issue Nov 2, 2023
Closed
@violetagg violetagg self-assigned this Nov 2, 2023
@violetagg violetagg added type/bug A general bug and removed ❓need-triage labels Nov 2, 2023
@violetagg violetagg added this to the 1.0.39 milestone Nov 2, 2023
violetagg added a commit that referenced this issue Nov 2, 2023
@violetagg
Ensure HttpServer connections.total metric is correct when connection…
3f87a9c 
… close happens before connection open

Fixes #2956
@violetagg violetagg mentioned this issue Nov 2, 2023
Merged
@violetagg violetagg linked a pull request Nov 2, 2023 that will close this issue
Ensure HttpServer connections.total metric is correct when connection close happens before connection open #2958
Merged
@violetagg
Copy link
Member Author

@jtorkkel Thanks for the detailed description. This is fixed with #2958.
If you can test the snapshots, it will be great!

@jtorkkel
Copy link

jtorkkel commented Nov 3, 2023

Thanks again,

Now works with snap, no more negative values.
I can see that TLS success result no opening/closing, but failing TLS attempts be seen from TLS errors.

I also managed to add CONNECTION_OPENED and CONNECTION_CLOSED total counts, which helps to monitor connection pool activity.


	@Override
	public void recordServerConnectionOpened(SocketAddress serverAddress) {
		String address = reactor.netty.Metrics.formatSocketAddress(serverAddress);
		Counter opened = MapUtils.computeIfAbsent(totalConnectionsOpenedCache, serverAddress.toString(),
				key -> filter(Counter.builder(name + CONNECTION_OPENED)
						.tags(LOCAL_ADDRESS, address)
						.register(REGISTRY)));
		if (opened != null) {
			opened.increment();
		}

		LongAdder totalConnectionAdder = getTotalConnectionsAdder(serverAddress);
		if (totalConnectionAdder != null) {
			totalConnectionAdder.increment();
		}
	}

@violetagg
Copy link
Member Author

@jtorkkel Great! Thanks for the testing!

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.39
3 participants
@violetagg @jtorkkel @reactorbot