jeudi 23 juin 2016

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: OutInterceptors OutFaultInterceptors The fun begins when InterceptorA calls a service, which throws a RuntimeException. 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... 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 OKrn....v20160210)rnrn>>>x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00...x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00}] 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]={<<<0rnrn>>>x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00...x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00}] 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><<<>>>x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00...x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00} 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 OKrn...x00x00x00x00x00x00x00x00x00x00x00x00x00x00x00} 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

Aucun commentaire:

Enregistrer un commentaire