CODEWITHSUNDEEP
javaapacheweb-servicessoapcxf
Atais
Atais

Reputation: 11275

How to handle Runtime Exception in Out Fault Interceptors, Apache CXF

We are using the newest version of Apache CXF 3.1.6 and I have found an interesting situation in our code.

Let's assume we have an interceptor called InterceptorA, in our case we want it to trigger for both normal and error output, so we have registered it in both:

The fun begins when InterceptorA calls a service, which throws a RuntimeException.

  1. If this happens during regular, out interceptors chain, the InterceptorA will be called twice! Because when RuntimeException is thrown. We enter out fault chain, call the InterceptorA again, then call the service again and...

  2. Inevitably we get a RuntimeException in out fault chain. Now, for the reason I do not understand, CXF returns an empty message with HTTP 200.

So...

For the double-call issue I was thinking about a simple flag in Message stating if the InterceptorA was called before. And if not we could do the regular. But the problem is still, when we are in out fault chain and the RuntimeExceptionoccurs.

Why is the result 200 OK? And why the body is empty?

To make the question complete I present a log from such a situation. I sped up the process. First we can see Fault: Service error which is a RuntimeException I have forced in the service. We enter the out fault chain and then I throw RuntimeException: Interceptor error. The next thing I can observe is an empty response in SoapUI.

16-06-22 19:12:36 [W] [LogUtils.java:449] Application {http://domain.com/service/}EEMediationServiceImplService#{http://domain.com/service/}transfer has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: Service error
    at org.apache.cxf.service.invoker.AbstractInvoker.createFault(AbstractInvoker.java:162) ~[cxf-core-3.1.6.jar:3.1.6]
    at org.apache.cxf.jaxws.AbstractJAXWSMethodInvoker.createFault(AbstractJAXWSMethodInvoker.java:267) ~[cxf-rt-frontend-jaxws-3.1.6.jar:3.1.6]
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:128) ~[cxf-core-3.1.6.jar:3.1.6]
    at org.apache.cxf.jaxws.AbstractJAXWSMethodInvoker.invoke(AbstractJAXWSMethodInvoker.java:232) ~[cxf-rt-frontend-jaxws-3.1.6.jar:3.1.6]
    at org.apache.cxf.jaxws.JAXWSMethodInvoker.invoke(JAXWSMethodInvoker.java:85) ~[cxf-rt-frontend-jaxws-3.1.6.jar:3.1.6]
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:74) ~[cxf-core-3.1.6.jar:3.1.6]
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59) ~[cxf-core-3.1.6.jar:3.1.6]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_91]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_91]
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor$2.run(ServiceInvokerInterceptor.java:126) ~[cxf-core-3.1.6.jar:3.1.6]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_91]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_91]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
Caused by: java.lang.RuntimeException: Service error
    at pl.ds.eemediation.service.INServiceStub.transfer(INServiceStub.java:64) ~[classes/:na]
    at pl.ds.eemediation.service.EEMediationServiceImpl.transfer(EEMediationServiceImpl.java:102) ~[classes/:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_91]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_91]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_91]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_91]
    at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:180) ~[cxf-core-3.1.6.jar:3.1.6]
    at org.apache.cxf.jaxws.JAXWSMethodInvoker.performInvocation(JAXWSMethodInvoker.java:66) ~[cxf-rt-frontend-jaxws-3.1.6.jar:3.1.6]
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) ~[cxf-core-3.1.6.jar:3.1.6]
    ... 10 common frames omitted
16-06-22 19:12:36 [W] [LogUtils.java:449] Application {http://domain.com/service/}EEMediationServiceImplService#{http://domain.com/service/}transfer has thrown exception, unwinding now
java.lang.RuntimeException: Interceptor error
    at pl.ds.eemediation.antifraud.interceptors.AntifraudInterceptor.handleMessage(AntifraudInterceptor.java:45) ~[classes/:na]
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) [cxf-core-3.1.6.jar:3.1.6]
    at org.apache.cxf.interceptor.AbstractFaultChainInitiatorObserver.onMessage(AbstractFaultChainInitiatorObserver.java:112) [cxf-core-3.1.6.jar:3.1.6]
    at org.apache.cxf.phase.PhaseInterceptorChain.wrapExceptionAsFault(PhaseInterceptorChain.java:366) [cxf-core-3.1.6.jar:3.1.6]
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:324) [cxf-core-3.1.6.jar:3.1.6]
    at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) [cxf-core-3.1.6.jar:3.1.6]
    at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:254) [cxf-rt-transports-http-3.1.6.jar:3.1.6]
    at org.apache.cxf.transport.http_jetty.JettyHTTPDestination.doService(JettyHTTPDestination.java:234) [cxf-rt-transports-http-jetty-3.1.6.jar:3.1.6]
    at org.apache.cxf.transport.http_jetty.JettyHTTPHandler.handle(JettyHTTPHandler.java:70) [cxf-rt-transports-http-jetty-3.1.6.jar:3.1.6]
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1129) [jetty-server-9.2.15.v20160210.jar:9.2.15.v20160210]
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1065) [jetty-server-9.2.15.v20160210.jar:9.2.15.v20160210]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [jetty-server-9.2.15.v20160210.jar:9.2.15.v20160210]
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215) [jetty-server-9.2.15.v20160210.jar:9.2.15.v20160210]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [jetty-server-9.2.15.v20160210.jar:9.2.15.v20160210]
    at org.eclipse.jetty.server.Server.handle(Server.java:499) [jetty-server-9.2.15.v20160210.jar:9.2.15.v20160210]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311) [jetty-server-9.2.15.v20160210.jar:9.2.15.v20160210]
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257) [jetty-server-9.2.15.v20160210.jar:9.2.15.v20160210]
    at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544) [jetty-io-9.2.15.v20160210.jar:9.2.15.v20160210]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635) [jetty-util-9.2.15.v20160210.jar:9.2.15.v20160210]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555) [jetty-util-9.2.15.v20160210.jar:9.2.15.v20160210]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
16-06-22 19:12:36 [D] [HttpConnection.java:657] org.eclipse.jetty.server.HttpConnection$SendCallback@5b033b51[PROCESSING][i=ResponseInfo{HTTP/1.1 200 null,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1cb2eb9d] generate: NEED_HEADER (null,[p=0,l=0,c=0,r=0],false)@START
16-06-22 19:12:36 [D] [HttpConnection.java:657] org.eclipse.jetty.server.HttpConnection$SendCallback@5b033b51[PROCESSING][i=ResponseInfo{HTTP/1.1 200 null,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1cb2eb9d] generate: FLUSH ([p=0,l=117,c=8192,r=117],[p=0,l=0,c=0,r=0],false)@COMMITTED
16-06-22 19:12:36 [D] [WriteFlusher.java:295] write: WriteFlusher@40c8dabd{IDLE} [HeapByteBuffer@e0d40e5[p=0,l=117,c=8192,r=117]={<<<HTTP/1.1 200 OK\r\n....v20160210)\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]
16-06-22 19:12:36 [D] [WriteFlusher.java:118] update WriteFlusher@40c8dabd{WRITING}:IDLE-->WRITING
16-06-22 19:12:36 [D] [ChannelEndPoint.java:188] flushed 117 SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,-,W,6543/200000,HttpConnection}{io=0,kio=0,kro=1}
16-06-22 19:12:36 [D] [WriteFlusher.java:118] update WriteFlusher@40c8dabd{IDLE}:WRITING-->IDLE
16-06-22 19:12:36 [D] [HttpConnection.java:657] org.eclipse.jetty.server.HttpConnection$SendCallback@5b033b51[PROCESSING][i=ResponseInfo{HTTP/1.1 200 null,-1,false},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@1cb2eb9d] generate: DONE ([p=117,l=117,c=8192,r=0],[p=0,l=0,c=0,r=0],false)@COMMITTED
16-06-22 19:12:36 [D] [Server.java:502] RESPONSE /eemediation-ws/EEMediationServicePort  200 handled=true
16-06-22 19:12:36 [D] [HttpChannelState.java:289] HttpChannelState@da912da{s=DISPATCHED i=true a=null} unhandle DISPATCHED
16-06-22 19:12:36 [D] [HttpConnection.java:657] org.eclipse.jetty.server.HttpConnection$SendCallback@5b033b51[PROCESSING][i=null,cb=Blocker@3b2f9996{null}] generate: CONTINUE (null,[p=0,l=0,c=0,r=0],true)@COMPLETING
16-06-22 19:12:36 [D] [HttpConnection.java:657] org.eclipse.jetty.server.HttpConnection$SendCallback@5b033b51[PROCESSING][i=null,cb=Blocker@3b2f9996{null}] generate: NEED_CHUNK (null,[p=0,l=0,c=0,r=0],true)@COMPLETING
16-06-22 19:12:36 [D] [HttpConnection.java:657] org.eclipse.jetty.server.HttpConnection$SendCallback@5b033b51[PROCESSING][i=null,cb=Blocker@3b2f9996{null}] generate: FLUSH (null,[p=0,l=0,c=0,r=0],true)@COMPLETING
16-06-22 19:12:36 [D] [WriteFlusher.java:295] write: WriteFlusher@40c8dabd{IDLE} [HeapByteBuffer@44cb4d4a[p=0,l=5,c=1024,r=5]={<<<0\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]
16-06-22 19:12:36 [D] [WriteFlusher.java:118] update WriteFlusher@40c8dabd{WRITING}:IDLE-->WRITING
16-06-22 19:12:36 [D] [ChannelEndPoint.java:188] flushed 5 SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,-,W,3/200000,HttpConnection}{io=0,kio=0,kro=1}
16-06-22 19:12:36 [D] [WriteFlusher.java:118] update WriteFlusher@40c8dabd{IDLE}:WRITING-->IDLE
16-06-22 19:12:36 [D] [HttpConnection.java:657] org.eclipse.jetty.server.HttpConnection$SendCallback@5b033b51[PROCESSING][i=null,cb=Blocker@3b2f9996{null}] generate: DONE (null,[p=0,l=0,c=0,r=0],true)@END
16-06-22 19:12:36 [D] [HttpConnection.java:373] unconsumed input HttpConnection@3359b3ac[FILLING,SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,-,-,1/200000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=CONTENT,877 of 877},g=HttpGenerator{s=END},c=HttpChannelOverHttp@38d29a84{r=1,c=true,a=COMPLETED,uri=/eemediation-ws/EEMediationServicePort}]
16-06-22 19:12:36 [D] [HttpParser.java:1232] parseNext s=CONTENT HeapByteBuffer@9b849ba[p=1229,l=1229,c=8192,r=0]={POST /eemediation...apenv:Envelope><<<>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
16-06-22 19:12:36 [D] [HttpParser.java:1587] CONTENT --> END
16-06-22 19:12:36 [D] [HttpChannel.java:705] HttpChannelOverHttp@38d29a84{r=1,c=true,a=COMPLETED,uri=/eemediation-ws/EEMediationServicePort} messageComplete
16-06-22 19:12:36 [D] [HttpInput.java:272] HttpInputOverHTTP@4b5e5f5a EOF
16-06-22 19:12:36 [D] [ChannelEndPoint.java:142] filled 0 SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,-,-,2/200000,HttpConnection}{io=0,kio=0,kro=1}
16-06-22 19:12:36 [D] [HttpConnection.java:322] HttpConnection@3359b3ac[FILLING,SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,-,-,3/200000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=END,877 of 877},g=HttpGenerator{s=END},c=HttpChannelOverHttp@38d29a84{r=1,c=true,a=COMPLETED,uri=/eemediation-ws/EEMediationServicePort}] filled 0
16-06-22 19:12:36 [D] [HttpInput.java:151] HttpInputOverHTTP@4b5e5f5a eof EOF
16-06-22 19:12:36 [D] [HttpParser.java:1563] reset HttpParser{s=END,877 of 877}
16-06-22 19:12:36 [D] [HttpParser.java:1587] END --> START
16-06-22 19:12:36 [D] [HttpChannel.java:448] HttpChannelOverHttp@38d29a84{r=1,c=false,a=IDLE,uri=} handle exit, result COMPLETE
16-06-22 19:12:36 [D] [ChannelEndPoint.java:142] filled 0 SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,-,-,6/200000,HttpConnection}{io=0,kio=0,kro=1}
16-06-22 19:12:36 [D] [ChannelEndPoint.java:142] filled 0 SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,-,-,6/200000,HttpConnection}{io=0,kio=0,kro=1}
16-06-22 19:12:36 [D] [HttpParser.java:1232] parseNext s=START HeapByteBuffer@e0d40e5[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
16-06-22 19:12:36 [D] [AbstractConnection.java:128] fillInterested HttpConnection@3359b3ac[FILLING,SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,-,-,7/200000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@38d29a84{r=1,c=false,a=IDLE,uri=}]
16-06-22 19:12:36 [D] [AbstractConnection.java:275] FILLING-->FILLING_FILL_INTERESTED HttpConnection@3359b3ac[FILLING_FILL_INTERESTED,SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,-,-,7/200000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@38d29a84{r=1,c=false,a=IDLE,uri=}]
16-06-22 19:12:36 [D] [AbstractConnection.java:275] FILLING_FILL_INTERESTED-->FILL_INTERESTED HttpConnection@3359b3ac[FILL_INTERESTED,SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,-,-,8/200000,HttpConnection}{io=0,kio=0,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator{s=START},c=HttpChannelOverHttp@38d29a84{r=1,c=false,a=IDLE,uri=}]
16-06-22 19:12:36 [D] [SelectChannelEndPoint.java:136] Local interests updating 0 -> 1 for SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,R,-,0/200000,HttpConnection}{io=1,kio=0,kro=1}
16-06-22 19:12:36 [D] [SelectorManager.java:480] Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@3cfd9e43
16-06-22 19:12:36 [D] [SelectorManager.java:602] Selector loop woken up from select, 0/1 selected
16-06-22 19:12:36 [D] [SelectorManager.java:525] Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@3cfd9e43
16-06-22 19:12:36 [D] [SelectChannelEndPoint.java:160] Key interests updated 0 -> 1 on SelectChannelEndPoint@7f7a6aa3{/127.0.0.1:58021<->18085,Open,in,out,R,-,2/200000,HttpConnection}{io=1,kio=1,kro=1}
16-06-22 19:12:36 [D] [SelectorManager.java:599] Selector loop waiting on select

Upvotes: 2

Views: 9341

Answers (1)

pedrofb
pedrofb

Reputation: 39271

I could reproduce your problem with JAX-RS and JAX-WS. Seems the exceptions thrown from the CXF interceptors escape the JAX-RS /JAX-WS flow and are not properly handled. See my response at Propagate exception from CXF interceptor to exception mapper for a similar case at client side.

A RuntimeException at interceptor.handleMessage generates a Fault and the response code is:

  • 200 if your service method returned originally 200. Body concatenates result and SoapFault
  • 500 if your service method returned originally other error code. Body has a SoapFault

A RuntimeException at interceptor.handleFault generates a Fault and the response code is: - 200 if your service method returned originally 200. Invalid Body. Received a SoapFault but XML is invalid - 200 if your service method returned originally other error code. Empty Body

Why is the result 200 OK?

It can only be a bug. For SOAP 1.2, the W3C spec specifies a status code of either 400 or 500 depending on the kind of fault. See table 20 at http://www.w3.org/TR/soap12-part2/#tabresstatereccodes

And why the body is empty?

The body is not empty in all cases. CXF 3.1.6 returns the SOAP fault in some cases, and what is really strange is that if service answered 200, concatenates the correct answer with soap fault!

Take a look at a real response I have performed

ID: 1
Response-Code: 200
Encoding: UTF-8
Content-Type: text/xml;charset=UTF-8
Headers: {Content-Length=[199], content-type=[text/xml;charset=UTF-8], Date=[Fri, 01 Jul 2016 06:12:40 GMT], Server=[Apache-Coyote/1.1]}
Payload: <soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/"><soap:Body><ns2:testWSResponse xmlns:ns2="http://test/"><return>name123</return></ns2:testWSResponse></soap:Body></soap:Envelope>

The double call to interceptors makes sense.

1) OutInterceptor1.handleMessage() --> RuntimeException

2) OutInterceptor1.handleFault() -->Called because handleMessage generated a Fault. Check javadoc of Interceptor

void handleFault(T message)

Called for all interceptors (in reverse order) on which handleMessage had been successfully invoked, when normal execution of the chain was aborted for some reason.

3) OutFaultInterceptor2.handleMessage() Called because OutInterceptor1 generated a Fault.

4) OutFaultInterceptor2.handleFault() Called because OutFaultInterceptor2.handleMessage() generated a Fault

Upvotes: 4

Related Questions