Uploaded image for project: 'CXF'
  1. CXF
  2. CXF-8124

CXF metrics - MetricsContext#stop called twice or without Fault in certain error cases

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 3.1.18, 3.3.3
    • Fix Version/s: 3.2.11, 3.3.4, 3.4.0
    • Component/s: Core
    • Labels:
      None
    • Estimated Complexity:
      Moderate

      Description

      While using the CXF metrics feature with a CXF REST client, in some situation there are incoherent calls to the MetricsContext#stop method. 2 cases can be isolated: server returns a 404 and the response body transmission is interrupted in the middle of the transfer.

      I wrote a unit test that allows to clearly reproduce the 2 use cases. Of course they are failing. The test prints out a stacktrace per call to the MetricsContext#stop method.

      notFoundStatusCode_stopCalledOnceWithFaultObjectInExchange

      [main] INFO cxf.reproducers.CxfMetricsIssueReproducerTest - MetricsContext#stop called 2 times
      [main] INFO cxf.reproducers.CxfMetricsIssueReproducerTest - - stop called with time = 16408651 ns, inSize = -1, outSize = 0, exchange that contains a FaultMode = false; callad at:
      [...]
      at org.apache.cxf.metrics.MetricsContext$$EnhancerByMockitoWithCGLIB$$1997d2d2.stop(<generated>)
      at org.apache.cxf.metrics.ExchangeMetrics.stop(ExchangeMetrics.java:75)
      at org.apache.cxf.metrics.interceptors.AbstractMetricsInterceptor.stop(AbstractMetricsInterceptor.java:215)
      at org.apache.cxf.metrics.interceptors.MetricsMessageInPostInvokeInterceptor.handleMessage(MetricsMessageInPostInvokeInterceptor.java:34)
      at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
      at org.apache.cxf.jaxrs.client.ClientMessageObserver.onMessage(ClientMessageObserver.java:56)
      at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1693)
      at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1570)
      at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1371)
      at org.apache.cxf.io.AbstractWrappedOutputStream.close(AbstractWrappedOutputStream.java:77)
      at org.apache.cxf.metrics.interceptors.CountingOutputStream.close(CountingOutputStream.java:47)
      at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)
      at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:671)
      at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63)
      at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
      at org.apache.cxf.jaxrs.client.AbstractClient.doRunInterceptorChain(AbstractClient.java:709)
      at org.apache.cxf.jaxrs.client.ClientProxyImpl.doChainedInvocation(ClientProxyImpl.java:887)
      at org.apache.cxf.jaxrs.client.ClientProxyImpl.invoke(ClientProxyImpl.java:335)
      at com.sun.proxy.$Proxy22.getBook(Unknown Source)
      at cxf.reproducers.CxfMetricsIssueReproducerTest.notFoundStatusCode_stopCalledOnceWithFaultObjectInExchange(CxfMetricsIssueReproducerTest.java:151)
      [...]
      [main] INFO cxf.reproducers.CxfMetricsIssueReproducerTest - - stop called with time = 26412378 ns, inSize = -1, outSize = 0, exchange that contains a FaultMode = true; callad at:
      [...]
      at org.apache.cxf.metrics.MetricsContext$$EnhancerByMockitoWithCGLIB$$1997d2d2.stop(<generated>)
      at org.apache.cxf.metrics.ExchangeMetrics.stop(ExchangeMetrics.java:75)
      at org.apache.cxf.metrics.interceptors.AbstractMetricsInterceptor.stop(AbstractMetricsInterceptor.java:215)
      at org.apache.cxf.metrics.interceptors.MetricsMessageInPostInvokeInterceptor.handleMessage(MetricsMessageInPostInvokeInterceptor.java:34)
      at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
      at org.apache.cxf.interceptor.AbstractFaultChainInitiatorObserver.onMessage(AbstractFaultChainInitiatorObserver.java:112)
      at org.apache.cxf.jaxrs.client.ClientProxyImpl.checkResponse(ClientProxyImpl.java:434)
      at org.apache.cxf.jaxrs.client.ClientProxyImpl.handleResponse(ClientProxyImpl.java:990)
      at org.apache.cxf.jaxrs.client.ClientProxyImpl.doChainedInvocation(ClientProxyImpl.java:895)
      at org.apache.cxf.jaxrs.client.ClientProxyImpl.invoke(ClientProxyImpl.java:335)
      at com.sun.proxy.$Proxy22.getBook(Unknown Source)
      at cxf.reproducers.CxfMetricsIssueReproducerTest.notFoundStatusCode_stopCalledOnceWithFaultObjectInExchange(CxfMetricsIssueReproducerTest.java:151)
      [...]

      incompleteResponse_stopCalledOnceWithFaultObjectInExchange

      [main] INFO cxf.reproducers.CxfMetricsIssueReproducerTest - MetricsContext#stop called 1 times
      [main] INFO cxf.reproducers.CxfMetricsIssueReproducerTest - - stop called with time = 14901568 ns, inSize = -1, outSize = 0, exchange that contains a FaultMode = false; callad at:
      [...]
      at org.apache.cxf.metrics.MetricsContext$$EnhancerByMockitoWithCGLIB$$1997d2d2.stop(<generated>)
      at org.apache.cxf.metrics.ExchangeMetrics.stop(ExchangeMetrics.java:75)
      at org.apache.cxf.metrics.interceptors.AbstractMetricsInterceptor.stop(AbstractMetricsInterceptor.java:215)
      at org.apache.cxf.metrics.interceptors.MetricsMessageInPostInvokeInterceptor.handleMessage(MetricsMessageInPostInvokeInterceptor.java:34)
      at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
      at org.apache.cxf.jaxrs.client.ClientMessageObserver.onMessage(ClientMessageObserver.java:56)
      at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1693)
      at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1570)
      at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1371)
      at org.apache.cxf.io.AbstractWrappedOutputStream.close(AbstractWrappedOutputStream.java:77)
      at org.apache.cxf.metrics.interceptors.CountingOutputStream.close(CountingOutputStream.java:47)
      at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)
      at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:671)
      at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63)
      at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
      at org.apache.cxf.jaxrs.client.AbstractClient.doRunInterceptorChain(AbstractClient.java:709)
      at org.apache.cxf.jaxrs.client.ClientProxyImpl.doChainedInvocation(ClientProxyImpl.java:887)
      at org.apache.cxf.jaxrs.client.ClientProxyImpl.invoke(ClientProxyImpl.java:335)
      at com.sun.proxy.$Proxy22.getBook(Unknown Source)
      at cxf.reproducers.CxfMetricsIssueReproducerTest.incompleteResponse_stopCalledOnceWithFaultObjectInExchange(CxfMetricsIssueReproducerTest.java:171)
      [...]

       

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                reta Andriy Redko
                Reporter:
                mederel Emile de Weerd
              • Votes:
                2 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 20m
                  20m