Hadrian Zbarcea created CXF-7394:
------------------------------------
Summary: Incorrect ERROR: Failed to send RM protocol message
Key: CXF-7394
URL: https://issues.apache.org/jira/browse/CXF-7394
Project: CXF
Issue Type: Bug
Components: WS-* Components
Reporter: Hadrian Zbarcea
Priority: Minor
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.
{code}
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.
{code}
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
