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

Revise HttpMetricsHandlerTests and fix testServerConnectionsRecorder #2391

Conversation

pderop
Copy link
Member

@pderop pderop commented Jul 18, 2022

This PR is a revamp of the HttpMetricsHandlerTests and also fixes a concurrency issue in testServerConnectionsRecorder, which sometimes fails with this 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 the testServerConnectionsRecorder asserts if the exception has not been thrown.

So, when doing this, we can then see the root cause exception (this exception comes from netty5 branch, bit it's the same issue in 1.0.x branch):

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);

when checkServerConnectionsRecorder() is called, the number of connections on the server is surprisingly 0 instead of 1 ! 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 eventually, but not immediately.

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.

The PR is also a big refactoring, where all observeDisconnect usage has been removed.

The tests are now based on the following handlers:

  • RequestReceivedHandler: this is a Server handler used to detect when the last http client request content has been received by the server. When the RequestReceivedHandler counts down its latch, it means the Server has received the last client request content data. This handler is placed after the HttpMetricsHandler, so the RequestReceivedHandler.channelRead method is called after the AbstractHttpServerMetricsHandler.recordRead is called. This ensures that all server metrics are up-to-date when the RequestReceivedHandler latch is counted down. The RequestReceivedHandler handler is only used by the testNonExistingEndpoint method, which may receive a 404 before the server has fully received the last client request content.
  • ResponseSentHandler: this is a Server handler used to detect when the last http response content has been sent to the client. The handler is placed before the HttpMetricsHandler. It means that the ResponseSentHandler promise listener will be called after the AbstractHttpServerMetricsHandler.write promise listener. This ensures that the server metrics are up-to-date when the ResponseSentHandler latch is counted down. The ResponseSentHandler is used by various tests which need to ensure that the last response content is sent by the server and that the server metrics are up-to-date
  • ServerCloseHandler: it's a Server handler used to wait until the client socket is closed on the server side.
  • ClientExceptionHandler: handler used by the testIssue896 test. Then handler counts the number of exceptions caught by the client. Metrics are up-to-date when the handler decrements its latch, because the handler is placed after the HttpClientMetricsHandler.

Lastly, pay attention to the usage of HttpClient.doAfterResponseSuccess in various tests: this method call is important: it ensures that the AbstractHttpClientMetricsHandler.channelRead method has received the LastHttpContent response, and the recordRead has then been called, so metrics are up-to-date.

Fixes #2368

@pderop pderop self-assigned this Jul 18, 2022
@pderop pderop added the type/bug A general bug label Jul 18, 2022
@pderop pderop added this to the 1.0.22 milestone Jul 18, 2022
@violetagg violetagg linked an issue Jul 18, 2022 that may be closed by this pull request
@pderop pderop marked this pull request as ready for review August 2, 2022 15:34
@pderop pderop requested a review from violetagg August 2, 2022 15:34
@pderop
Copy link
Member Author

pderop commented Aug 2, 2022

mmm, I forgot to push one polishing commit, please wait a moment before reviewing ...

@pderop
Copy link
Member Author

pderop commented Aug 2, 2022

now, it is ok.

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 keep formatting changes (when needed) in a separate change, it will be easier for the one that is reviewing the change.

@pderop
Copy link
Member Author

pderop commented Aug 3, 2022

thanks Violeta, I have applied your suggestions, please re-take a look ?

@pderop
Copy link
Member Author

pderop commented Aug 3, 2022

by the way, the error for macos-11/nio is unrelated to the changes.

@pderop
Copy link
Member Author

pderop commented Aug 3, 2022

mmm, please wait, I need to check the windows error ...

@pderop
Copy link
Member Author

pderop commented Aug 3, 2022

ok, the windows error is also unrelated to the changes.

@pderop
Copy link
Member Author

pderop commented Aug 3, 2022

@violetagg , thank you for your review.

@pderop pderop merged commit 115257b into reactor:1.0.x Aug 3, 2022
pderop added a commit that referenced this pull request Aug 3, 2022
pderop added a commit that referenced this pull request Aug 3, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type/bug A general bug
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Revise HttpMetricsHandlerTests#testServerConnectionsRecorder
2 participants