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

Incorrect ERROR: Failed to send RM protocol message

Attach filesAttach ScreenshotVotersWatch issueWatchersCreate sub-taskLinkCloneUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 3.1.7, 3.1.10
    • Fix Version/s: 3.1.12, 3.2.0
    • Component/s: WS-* Components
    • Labels:
      None
    • Estimated Complexity:
      Unknown

      Description

      The WS-RM protocol sends out-f-band messages. When the service goes down, for instance, if the client attempts to CloseSequence (out-of-band, see below) the request will clearly fail.

      The behavior of the RM feature looks correct (to me), however the log incorrectly shows the ERROR which creates unnecessary confusion. The recommendation is to catch it and only get a WARN in the logs.

      2017-06-05 15:18:25,297 | INFO  | ion(3)-127.0.0.1 | REQ_OUT                          | 41 - org.apache.cxf.cxf-rt-features-logging - 3.1.10 | <soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
        <soap:Header>
          <Action xmlns="http://www.w3.org/2005/08/addressing">http://docs.oasis-open.org/ws-rx/wsrm/200702/CloseSequence</Action>
          <MessageID xmlns="http://www.w3.org/2005/08/addressing">urn:uuid:db7ae5ef-6ee4-4d1b-865c-f6e19c14dc74</MessageID>
          <To xmlns="http://www.w3.org/2005/08/addressing">http://localhost:8181/cxf/greeter-wsrm</To>
          <ReplyTo xmlns="http://www.w3.org/2005/08/addressing">
            <Address>http://www.w3.org/2005/08/addressing/anonymous</Address>
          </ReplyTo>
        </soap:Header>
        <soap:Body>
          <CloseSequence xmlns="http://docs.oasis-open.org/ws-rx/wsrm/200702" xmlns:ns2="http://www.w3.org/2005/08/addressing">
            <Identifier>urn:uuid:693f8fe0-f239-4549-8b6e-6ee01663f9c5</Identifier>
            <LastMsgNumber>3</LastMsgNumber>
          </CloseSequence>
        </soap:Body>
      </soap:Envelope>
      
      2017-06-05 15:18:25,298 | WARN  | qtp8911442-113   | ServletController                | 47 - org.apache.cxf.cxf-rt-transports-http - 3.1.10 | Can't find the the request for http://localhost:8181/cxf/greeter-wsrm's Observer 
      2017-06-05 15:18:25,301 | WARN  | ion(3)-127.0.0.1 | PhaseInterceptorChain            | 37 - org.apache.cxf.cxf-core - 3.1.10 | Interceptor for {http://docs.oasis-open.org/ws-rx/wsrm/200702}SequenceAbstractService#{http://docs.oasis-open.org/ws-rx/wsrm/200702}CloseSequence has thrown exception, unwinding now
      org.apache.cxf.interceptor.Fault: Could not send Message.
      	at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:64)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.endpoint.ClientImpl.doInvoke(ClientImpl.java:514)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:423)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.ws.rm.Proxy.invoke(Proxy.java:317)[51:org.apache.cxf.cxf-rt-ws-rm:3.1.10]
      	at org.apache.cxf.ws.rm.Proxy.invoke(Proxy.java:334)[51:org.apache.cxf.cxf-rt-ws-rm:3.1.10]
      	at org.apache.cxf.ws.rm.Proxy.lastMessage(Proxy.java:240)[51:org.apache.cxf.cxf-rt-ws-rm:3.1.10]
      	at org.apache.cxf.ws.rm.RMEndpoint.shutdown(RMEndpoint.java:819)[51:org.apache.cxf.cxf-rt-ws-rm:3.1.10]
      	at org.apache.cxf.ws.rm.RMManager.shutdown(RMManager.java:512)[51:org.apache.cxf.cxf-rt-ws-rm:3.1.10]
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_131]
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_131]
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_131]
      	at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_131]
      	at org.apache.cxf.common.injection.ResourceInjector.invokePreDestroy(ResourceInjector.java:366)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.common.injection.ResourceInjector.destroy(ResourceInjector.java:139)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.bus.extension.ExtensionManagerImpl.destroyBeans(ExtensionManagerImpl.java:392)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.bus.extension.ExtensionManagerBus.destroyBeans(ExtensionManagerBus.java:317)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.bus.extension.ExtensionManagerBus.shutdown(ExtensionManagerBus.java:331)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.bus.extension.ExtensionManagerBus.shutdown(ExtensionManagerBus.java:313)[37:org.apache.cxf.cxf-core:3.1.10]
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_131]
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_131]
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_131]
      	at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_131]
      	at org.apache.aries.blueprint.utils.ReflectionUtils.invoke(ReflectionUtils.java:299)
      	at org.apache.aries.blueprint.container.BeanRecipe.invoke(BeanRecipe.java:980)
      	at org.apache.aries.blueprint.container.BeanRecipe.destroy(BeanRecipe.java:887)
      	at org.apache.aries.blueprint.container.BlueprintRepository.destroy(BlueprintRepository.java:329)
      	at org.apache.aries.blueprint.container.BlueprintContainerImpl.destroyComponents(BlueprintContainerImpl.java:765)
      	at org.apache.aries.blueprint.container.BlueprintContainerImpl.tidyupComponents(BlueprintContainerImpl.java:964)
      	at org.apache.aries.blueprint.container.BlueprintContainerImpl.destroy(BlueprintContainerImpl.java:909)
      	at org.apache.aries.blueprint.container.BlueprintExtender$3.run(BlueprintExtender.java:325)
      	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_131]
      	at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_131]
      	at org.apache.aries.blueprint.container.BlueprintExtender.destroyContainer(BlueprintExtender.java:346)
      	at org.apache.aries.blueprint.container.BlueprintExtender.modifiedBundle(BlueprintExtender.java:238)
      	at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:500)
      	at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:433)
      	at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$AbstractTracked.track(BundleHookBundleTracker.java:725)
      	at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.bundleChanged(BundleHookBundleTracker.java:463)
      	at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEventHook.event(BundleHookBundleTracker.java:422)
      	at org.apache.felix.framework.util.SecureAction.invokeBundleEventHook(SecureAction.java:1179)
      	at org.apache.felix.framework.EventDispatcher.createWhitelistFromHooks(EventDispatcher.java:730)
      	at org.apache.felix.framework.EventDispatcher.fireBundleEvent(EventDispatcher.java:485)
      	at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541)
      	at org.apache.felix.framework.Felix.stopBundle(Felix.java:2600)
      	at org.apache.felix.framework.BundleImpl.stop(BundleImpl.java:1038)
      	at org.apache.felix.framework.BundleImpl.stop(BundleImpl.java:1024)
      	at org.apifocal.demo.wsrm.itests.GreeterClientTest.testCall(GreeterClientTest.java:90)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_131]
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_131]
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_131]
      	at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_131]
      	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
      	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
      	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
      	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
      	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
      	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
      	at org.ops4j.pax.exam.invoker.junit.internal.ContainerTestRunner.runLeafWithRetry(ContainerTestRunner.java:97)
      	at org.ops4j.pax.exam.invoker.junit.internal.ContainerTestRunner.runChildWithRetry(ContainerTestRunner.java:84)
      	at org.ops4j.pax.exam.invoker.junit.internal.ContainerTestRunner.runChild(ContainerTestRunner.java:75)
      	at org.ops4j.pax.exam.invoker.junit.internal.ContainerTestRunner.runChild(ContainerTestRunner.java:44)
      	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
      	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
      	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
      	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
      	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
      	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
      	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
      	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
      	at org.ops4j.pax.exam.invoker.junit.internal.JUnitProbeInvoker.invokeViaJUnit(JUnitProbeInvoker.java:124)
      	at org.ops4j.pax.exam.invoker.junit.internal.JUnitProbeInvoker.findAndInvoke(JUnitProbeInvoker.java:97)
      	at org.ops4j.pax.exam.invoker.junit.internal.JUnitProbeInvoker.call(JUnitProbeInvoker.java:73)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_131]
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_131]
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_131]
      	at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_131]
      	at org.ops4j.pax.exam.rbc.internal.RemoteBundleContextImpl.remoteCall(RemoteBundleContextImpl.java:83)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_131]
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_131]
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_131]
      	at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_131]
      	at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:346)[:1.8.0_131]
      	at sun.rmi.transport.Transport$1.run(Transport.java:200)[:1.8.0_131]
      	at sun.rmi.transport.Transport$1.run(Transport.java:197)[:1.8.0_131]
      	at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_131]
      	at sun.rmi.transport.Transport.serviceCall(Transport.java:196)[:1.8.0_131]
      	at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:568)[:1.8.0_131]
      	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826)[:1.8.0_131]
      	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:683)[:1.8.0_131]
      	at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_131]
      	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682)[:1.8.0_131]
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_131]
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_131]
      	at java.lang.Thread.run(Thread.java:748)[:1.8.0_131]
      Caused by: org.apache.cxf.transport.http.HTTPException: HTTP response '404: Not Found' when communicating with http://localhost:8181/cxf/greeter-wsrm
      	at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.doProcessResponseCode(HTTPConduit.java:1608)[47:org.apache.cxf.cxf-rt-transports-http:3.1.10]
      	at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1615)[47:org.apache.cxf.cxf-rt-transports-http:3.1.10]
      	at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1559)[47:org.apache.cxf.cxf-rt-transports-http:3.1.10]
      	at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1356)[47:org.apache.cxf.cxf-rt-transports-http:3.1.10]
      	at org.apache.cxf.io.CacheAndWriteOutputStream.postClose(CacheAndWriteOutputStream.java:56)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.io.CachedOutputStream.close(CachedOutputStream.java:216)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)[37:org.apache.cxf.cxf-core:3.1.10]
      	at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:653)[47:org.apache.cxf.cxf-rt-transports-http:3.1.10]
      	at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:62)[37:org.apache.cxf.cxf-core:3.1.10]
      	... 94 more
      2017-06-05 15:18:25,333 | ERROR | ion(3)-127.0.0.1 | Proxy                            | 51 - org.apache.cxf.cxf-rt-ws-rm - 3.1.10 | Failed to send RM protocol message {http://docs.oasis-open.org/ws-rx/wsrm/200702}CloseSequence.
      org.apache.cxf.interceptor.Fault: Could not send Message.
      

        Attachments

          Activity

            People

            • Assignee:
              dkulp Daniel Kulp
              Reporter:
              hadrian Hadrian Zbarcea

              Dates

              • Created:
                Updated:
                Resolved:

                Issue deployment