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

Stabilize HttpMetricsHandlerTests#testServerConnectionsRecorder #2370

Closed

Conversation

pderop
Copy link
Member

@pderop pderop commented Jul 9, 2022

Sometimes, the HttpMetricsHandlerTests.testServerConnectionsRecorder() test fails with the following exception:

HttpMetricsHandlerTests > testServerConnectionsRecorder(HttpProtocol[], HttpProtocol[], ProtocolSslContextSpec, ProtocolSslContextSpec, HttpProtocol) > reactor.netty.http.HttpMetricsHandlerTests.testServerConnectionsRecorder(HttpProtocol[], HttpProtocol[], ProtocolSslContextSpec, ProtocolSslContextSpec, HttpProtocol)[8] FAILED
    java.lang.AssertionError: expectation "expectNext(Hello World!)" failed (expected: onNext(Hello World!); actual: onError(reactor.netty.http.client.PrematureCloseException: Connection prematurely closed DURING response))
        at reactor.test.MessageFormatter.assertionError(MessageFormatter.java:115)
        at reactor.test.MessageFormatter.failPrefix(MessageFormatter.java:104)
        at reactor.test.MessageFormatter.fail(MessageFormatter.java:73)
        at reactor.test.MessageFormatter.failOptional(MessageFormatter.java:88)
        at reactor.test.DefaultStepVerifierBuilder.lambda$addExpectedValue$10(DefaultStepVerifierBuilder.java:509)
        at reactor.test.DefaultStepVerifierBuilder$SignalEvent.test(DefaultStepVerifierBuilder.java:2288)
        at reactor.test.DefaultStepVerifierBuilder$DefaultVerifySubscriber.onSignal(DefaultStepVerifierBuilder.java:1528)
        at reactor.test.DefaultStepVerifierBuilder$DefaultVerifySubscriber.onExpectation(DefaultStepVerifierBuilder.java:1476)
        at reactor.test.DefaultStepVerifierBuilder$DefaultVerifySubscriber.onError(DefaultStepVerifierBuilder.java:1129)
        at reactor.core.publisher.FluxHandle$HandleSubscriber.onError(FluxHandle.java:210)
        at reactor.core.publisher.FluxMap$MapConditionalSubscriber.onError(FluxMap.java:265)
        at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onError(FluxDoFinally.java:119)
        at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onError(FluxHandleFuseable.java:226)
        at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121)
        at reactor.core.publisher.MonoCollectList$MonoCollectListSubscriber.onError(MonoCollectList.java:114)
        at reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:134)
        at reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:134)
        at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onError(MonoFlatMapMany.java:255)
        at reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:134)
        at reactor.netty.channel.FluxReceive.onInboundError(FluxReceive.java:450)
        at reactor.netty.channel.ChannelOperations.onInboundError(ChannelOperations.java:492)
        at reactor.netty.http.client.HttpClientOperations.onInboundClose(HttpClientOperations.java:272)
        at reactor.netty.channel.ChannelOperationsHandler.channelInactive(ChannelOperationsHandler.java:70)
        at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelInactive(DefaultChannelHandlerContext.java:284)
        at io.netty5.channel.DefaultChannelHandlerContext.findAndInvokeChannelInactive(DefaultChannelHandlerContext.java:278)
        at io.netty5.channel.DefaultChannelHandlerContext.fireChannelInactive(DefaultChannelHandlerContext.java:265)
        at io.netty5.channel.ChannelHandler.channelInactive(ChannelHandler.java:213)
        at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelInactive(DefaultChannelHandlerContext.java:284)
        at io.netty5.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:808)
        at io.netty5.handler.codec.http2.DefaultHttp2StreamChannel.lambda$fireChannelInactiveAndDeregister$2(DefaultHttp2StreamChannel.java:610)
        at io.netty5.util.concurrent.SingleThreadEventExecutor.runTask(SingleThreadEventExecutor.java:338)
        at io.netty5.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:361)
        at io.netty5.channel.SingleThreadEventLoop.run(SingleThreadEventLoop.java:[180](https://github.com/reactor/reactor-netty/runs/7250727386?check_suite_focus=true#step:11:181))
        at io.netty5.util.concurrent.SingleThreadEventExecutor.lambda$doStartThread$4(SingleThreadEventExecutor.java:774)
        at io.netty5.util.internal.ThreadExecutorMap.lambda$apply$1(ThreadExecutorMap.java:68)
        at io.netty5.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:833)

Such exception can happen if the checkServerConnectionsRecorder method throws some exceptions.
So, the PR first catches any exceptions thrown from checkServerConnectionsRecorder, and then display it from the testServerConnectionsRecorder method.

So, we can now observe this root cause exception:

HttpMetricsHandlerTests > testServerConnectionsRecorder(HttpProtocol[], HttpProtocol[], ProtocolSslContextSpec, ProtocolSslContextSpec, HttpProtocol) > reactor.netty.http.HttpMetricsHandlerTests.testServerConnectionsRecorder(HttpProtocol[], HttpProtocol[], ProtocolSslContextSpec, ProtocolSslContextSpec, HttpProtocol)[4] FAILED
    org.opentest4j.AssertionFailedError: 
    expected: 
      null
     but was: 
      org.opentest4j.AssertionFailedError: 
      expected: 1
       but was: 0
      	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
      	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
      	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
      	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
      	at reactor.netty.http.HttpMetricsHandlerTests.checkServerConnectionsRecorder(HttpMetricsHandlerTests.java:768)
      	at reactor.netty.http.HttpMetricsHandlerTests.lambda$setUp$9(HttpMetricsHandlerTests.java:157)
      	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:185)
      	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:122)
      	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:122)
      	at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:279)
      	at reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:388)
      	at reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:408)
      	at reactor.netty.http.server.HttpServerOperations.onInboundNext(HttpServerOperations.java:579)
      	at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:94)
      	at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:437)
      	at io.netty5.channel.DefaultChannelHandlerContext.findAndInvokeChannelRead(DefaultChannelHandlerContext.java:430)
      	at io.netty5.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:411)
      	at reactor.netty.http.server.AbstractHttpServerMetricsHandler.channelRead(AbstractHttpServerMetricsHandler.java:192)
      	at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:437)
      	at io.netty5.channel.DefaultChannelHandlerContext.findAndInvokeChannelRead(DefaultChannelHandlerContext.java:430)
      	at io.netty5.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:411)
      	at reactor.netty.http.server.Http2StreamBridgeServerHandler.channelRead(Http2StreamBridgeServerHandler.java:142)
      	at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:437)
      	at io.netty5.channel.DefaultChannelHandlerContext.findAndInvokeChannelRead(DefaultChannelHandlerContext.java:430)
      	at io.netty5.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:411)
      	at io.netty5.handler.codec.http2.Http2StreamFrameToHttpObjectCodec.decodeAndClose(Http2StreamFrameToHttpObjectCodec.java:125)
      	at io.netty5.handler.codec.http2.Http2StreamFrameToHttpObjectCodec.decodeAndClose(Http2StreamFrameToHttpObjectCodec.java:57)
      	at io.netty5.handler.codec.MessageToMessageCodec$2.decodeAndClose(MessageToMessageCodec.java:83)
      	at io.netty5.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:87)
      	at io.netty5.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:113)
      	at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:437)
      	at io.netty5.channel.DefaultChannelHandlerContext.findAndInvokeChannelRead(DefaultChannelHandlerContext.java:430)
      	at io.netty5.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:411)
      	at io.netty5.channel.ChannelHandler.channelRead(ChannelHandler.java:234)
      	at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:437)
      	at io.netty5.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:832)
      	at io.netty5.handler.codec.http2.DefaultHttp2StreamChannel.doRead0(DefaultHttp2StreamChannel.java:786)
      	at io.netty5.handler.codec.http2.DefaultHttp2StreamChannel.fireChildRead(DefaultHttp2StreamChannel.java:400)
      	at io.netty5.handler.codec.http2.Http2MultiplexHandler.channelRead(Http2MultiplexHandler.java:173)
      	at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:437)
      	at io.netty5.channel.DefaultChannelHandlerContext.findAndInvokeChannelRead(DefaultChannelHandlerContext.java:430)
      	at io.netty5.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:411)
      	at io.netty5.channel.internal.DelegatingChannelHandlerContext.fireChannelRead(DelegatingChannelHandlerContext.java:113)
      	at io.netty5.handler.codec.ByteToMessageDecoder$ByteToMessageDecoderContext.fireChannelRead(ByteToMessageDecoder.java:437)
      	at io.netty5.handler.codec.http2.Http2FrameCodec.onHttp2Frame(Http2FrameCodec.java:689)
      	at io.netty5.handler.codec.http2.Http2FrameCodec$FrameListener.onDataRead(Http2FrameCodec.java:632)
      	at io.netty5.handler.codec.http2.Http2FrameListenerDecorator.onDataRead(Http2FrameListenerDecorator.java:37)
      	at io.netty5.handler.codec.http2.Http2EmptyDataFrameListener.onDataRead(Http2EmptyDataFrameListener.java:49)
      	at io.netty5.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onDataRead(DefaultHttp2ConnectionDecoder.java:307)
      	at io.netty5.handler.codec.http2.Http2InboundFrameLogger$1.onDataRead(Http2InboundFrameLogger.java:49)
      	at io.netty5.handler.codec.http2.DefaultHttp2FrameReader.readDataFrame(DefaultHttp2FrameReader.java:411)
      	at io.netty5.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:246)
      	at io.netty5.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:158)
      	at io.netty5.handler.codec.http2.Http2InboundFrameLogger.readFrame(Http2InboundFrameLogger.java:42)
      	at io.netty5.handler.codec.http2.DefaultHttp2ConnectionDecoder.decodeFrame(DefaultHttp2ConnectionDecoder.java:173)
      	at io.netty5.handler.codec.http2.DecoratingHttp2ConnectionDecoder.decodeFrame(DecoratingHttp2ConnectionDecoder.java:61)
      	at io.netty5.handler.codec.http2.Http2ConnectionHandler$FrameDecoder.decode(Http2ConnectionHandler.java:391)
      	at io.netty5.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:451)
      	at io.netty5.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:378)
      	at io.netty5.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:321)
      	at io.netty5.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:202)
      	at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:437)
      	at io.netty5.channel.DefaultChannelHandlerContext.findAndInvokeChannelRead(DefaultChannelHandlerContext.java:430)
      	at io.netty5.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:411)
      	at reactor.netty.channel.AbstractChannelMetricsHandler.channelRead(AbstractChannelMetricsHandler.java:116)
      	at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:437)
      	at io.netty5.channel.DefaultChannelHandlerContext.findAndInvokeChannelRead(DefaultChannelHandlerContext.java:430)
      	at io.netty5.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:411)
      	at io.netty5.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:280)
      	at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:437)
      	at io.netty5.channel.DefaultChannelHandlerContext.findAndInvokeChannelRead(DefaultChannelHandlerContext.java:430)
      	at io.netty5.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:411)
      	at io.netty5.channel.internal.DelegatingChannelHandlerContext.fireChannelRead(DelegatingChannelHandlerContext.java:113)
      	at io.netty5.handler.codec.ByteToMessageDecoder$ByteToMessageDecoderContext.fireChannelRead(ByteToMessageDecoder.java:437)
      	at io.netty5.handler.ssl.SslHandler.unwrap(SslHandler.java:1205)
      	at io.netty5.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1071)
      	at io.netty5.handler.ssl.SslHandler.decode(SslHandler.java:1118)
      	at io.netty5.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:378)
      	at io.netty5.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:321)
      	at io.netty5.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:202)
      	at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:437)
      	at io.netty5.channel.DefaultChannelHandlerContext.findAndInvokeChannelRead(DefaultChannelHandlerContext.java:430)
      	at io.netty5.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:411)
      	at io.netty5.channel.ChannelHandler.channelRead(ChannelHandler.java:234)
      	at io.netty5.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:437)
      	at io.netty5.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:832)
      	at io.netty5.channel.epoll.AbstractEpollStreamChannel.epollInReady(AbstractEpollStreamChannel.java:485)
      	at io.netty5.channel.epoll.EpollHandler.processReady(EpollHandler.java:445)
      	at io.netty5.channel.epoll.EpollHandler.run(EpollHandler.java:364)
      	at io.netty5.channel.SingleThreadEventLoop.runIO(SingleThreadEventLoop.java:192)
      	at io.netty5.channel.SingleThreadEventLoop.run(SingleThreadEventLoop.java:176)
      	at io.netty5.util.concurrent.SingleThreadEventExecutor.lambda$doStartThread$4(SingleThreadEventExecutor.java:774)
      	at io.netty5.util.internal.ThreadExecutorMap.lambda$apply$1(ThreadExecutorMap.java:68)
      	at io.netty5.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
      	at java.base/java.lang.Thread.run(Thread.java:833)
        at java.base@17.0.3/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at java.base@17.0.3/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
        at java.base@17.0.3/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.base@17.0.3/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
        at app//reactor.netty.http.HttpMetricsHandlerTests.testServerConnectionsRecorder(HttpMetricsHandlerTests.java:668)

So, what is failing is this check from checkServerConnectionsRecorder method:

    assertThat(ServerRecorder.INSTANCE.onServerConnectionsAmount.get()).isEqualTo(1);

So, when checkServerConnectionsRecorder() is called, the number of connections on the server is surprisingly 0 instead of 1 !

I think it's a concurrency issue which may happen if CI is slow. Here is the reproducer scenario I can imagine for the moment:

  • we are testing an HTTP2 test, and the test succeeds, so when tearDown is called, the client connection provider is disposed. But because the system is slow, the server does not immediately see the close, it will see it very shortly, in few nanoseconds

  • so, the next test is now executing, and then the ServerRecorder.recordServerConnectionOpened() is called: onServerConnectionsAmount is set to 1, but right after, recordServerConnectionClosed is called because the previous server test is still closing -> in this case, onServerConnectionsAmount is decremented and is wrongly set to 0

The PR is an attempt to fix this issue: it first dispose the client connection provider, then it waits for the recordServerConnectionClosed to be called, then it asserts the test expectations. This patch also simplifies a bit the test because the "done" CountDownLatch has been removed, and a new "ServerCloseHandler" is used to ensure the server has seen its client socket closed.

Now, using the patch, I restarted the CI many times and could not reproduce the problem anymore.

@pderop pderop changed the title Stabilize HttpMetricsHandlerTests Stabilize HttpMetricsHandlerTests#testServerConnectionsRecorder Jul 11, 2022
@pderop pderop requested a review from violetagg July 11, 2022 10:12
@pderop pderop added the type/enhancement A general enhancement label Jul 11, 2022
@pderop pderop added this to the 2.0.0-M1 milestone Jul 11, 2022
@pderop
Copy link
Member Author

pderop commented Jul 11, 2022

@violetagg , please hold on before reviewing, I may have to cleanup something before. thanks.

@pderop
Copy link
Member Author

pderop commented Jul 11, 2022

@violetagg, the cleanup I had in mind does not work for the moment, so can you please review ?
thanks

…verCloseHandler in order to ensure the server has closed the client socket
@violetagg violetagg modified the milestones: 2.0.0-M1, 2.0.0-M2 Jul 11, 2022
Copy link
Member

@violetagg violetagg left a comment

Choose a reason for hiding this comment

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

Please base this PR on top of 1.0.x branch

},
Function.identity())
.doOnConnection(c -> ServerCloseHandler.register(c, serverCloseLatch, isHttp11))
.metrics(true, () -> ServerRecorder.INSTANCE, Function.identity())
Copy link
Member

Choose a reason for hiding this comment

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

Do we need this to be always a new Supplier?

@violetagg violetagg modified the milestones: 2.0.0-M1, 1.0.22 Jul 13, 2022
@pderop
Copy link
Member Author

pderop commented Jul 18, 2022

Closing this PR, which will be superseded by another 1.0.x upcoming PR.

@pderop pderop closed this Jul 18, 2022
@violetagg
Copy link
Member

This is superseded by #2391

@violetagg violetagg added the status/superseded An issue that has been superseded by another label Jul 21, 2022
@violetagg violetagg removed this from the 1.0.22 milestone Jul 21, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status/superseded An issue that has been superseded by another type/enhancement A general enhancement
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants