You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cxf.apache.org by Yeroc <cp...@gmail.com> on 2007/10/24 23:36:34 UTC
Unintended Consequences...
All...
I've got a very puzzling problem issue with CXF v2.0.1. I implemented a
SOAPHandler that logs all the SOAP messages being sent over the wire. It's
very similar to the one that ships as an example in the CXF distribution
except that I'm logging to a log4j Logger.
What's strange is that in one case the behavior of my SOAP service changes
depending on whether the logging is enabled or not! (The SOAPHandler itself
is enabled always, just the logging of the messages is enabled/disabled at
runtime.) Even stranger, is that when the logging is enabled the service is
working fine, but when the logging is disabled, the service errors with an
unmarshalling error (see below).
Logging a SOAP message shouldn't be affecting the parsing of a message in
any way. Here's the relevant code:
private void log(SOAPMessageContext smc)
{
if (!log.isTraceEnabled()) return;
Boolean outbound =
(Boolean)smc.get(MessageContext.MESSAGE_OUTBOUND_PROPERTY);
SOAPMessage msg = smc.getMessage();
try
{
if (outbound.booleanValue())
{ los.write(">\n".getBytes()); }
else
{ los.write("<\n".getBytes()); }
msg.writeTo(los);
los.flush();
}
catch (Exception e)
{ log.error(e.getMessage(), e); }
}
It seems to me that either SOAPMessageContext.getMessage() or
SOAPMessage.writeTo() must have some sort of sideaffect?!? Surely this
can't be intended?
Here's the error I'm getting when logging is NOT enabled (the code above
returns on the initial if condition check):
Oct 23, 2007 5:02:51 PM org.apache.cxf.phase.PhaseInterceptorChain
doIntercept
INFO: Interceptor has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: Unmarshalling Error : Current state not
START_ELEMENT or END_ELEMENT
at
org.apache.cxf.jaxb.JAXBEncoderDecoder.unmarshallArray(JAXBEncoderDecoder.java:443)
at
org.apache.cxf.jaxb.JAXBEncoderDecoder.unmarshall(JAXBEncoderDecoder.java:256)
at
org.apache.cxf.jaxb.io.DataReaderImpl.read(DataReaderImpl.java:40)
at
org.apache.cxf.interceptor.DocLiteralInInterceptor.getPara(DocLiteralInInterceptor.java:235)
at
org.apache.cxf.interceptor.DocLiteralInInterceptor.handleMessage(DocLiteralInInterceptor.java:121)
at
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:207)
at
org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:73)
at
org.apache.cxf.transport.servlet.ServletDestination.doMessage(ServletDestination.java:78)
at
org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:231)
at
org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:139)
at com.kelman.kws.v2.CXFServlet.invoke(CXFServlet.java:121)
at com.kelman.kws.v2.CXFServlet.doPost(CXFServlet.java:92)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at
org.apache.catalina.valves.FastCommonAccessLogValve.invoke(FastCommonAccessLogValve.java:495)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at
org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
at
org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:664)
at
org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
at
org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:595)
Caused by: java.lang.IllegalStateException: Current state not START_ELEMENT
or END_ELEMENT
at
com.ctc.wstx.sr.BasicStreamReader.getName(BasicStreamReader.java:721) at
org.apache.cxf.staxutils.DepthXMLStreamReader.getName(DepthXMLStreamReader.java:109)
at
org.apache.cxf.jaxb.JAXBEncoderDecoder.unmarshallArray(JAXBEncoderDecoder.java:426)
... 28 more
Does anyone have any ideas on what is going on?
Thanks,
Corey
--
View this message in context: http://www.nabble.com/Unintended-Consequences...-tf4687206.html#a13395660
Sent from the cxf-user mailing list archive at Nabble.com.
Re: Unintended Consequences...
Posted by Daniel Kulp <dk...@apache.org>.
You probably hit a bug in the SAAJ implementation where it doesn't really
parse thing completely until asked for, but the DOMSource stuff doesn't
ask for it in a way it expects. This MIGHT be fixed for 2.0.2 or
2.0.3-SNAPSHOT as I did add a bunch of "soapMsg.getEnvelope().getBody()"
calls in the code to force it to parse fully. Can you try the
2.0.3-SNAPSHOT and see if that helps?
http://people.apache.org/repo/m2-snapshot-repository/org/apache/cxf/apache-cxf/2.0.3-incubator-SNAPSHOT/
If not, I MAY be able to get a fix in place before 2.0.3 is released.
(couple days now)
Couple notes:
1) You could do:
SOAPMessage msg = smc.getMessage();
msg.getEnvelope().getBody();
if (!log.isTraceEnabled()) return;
That would probably fix it.
2) This is really a "slow" way of logging. You parse the XML, then
regenerate the XML by walking the tree, then we have to re-walk the tree
to deserialize, etc.... I'd suggest using the LoggingInInterceptor
(or at least look at the code and use that as a model) that we already
have that will log at the stream level.
Dan
On Wednesday 24 October 2007, Yeroc wrote:
> All...
>
> I've got a very puzzling problem issue with CXF v2.0.1. I implemented
> a SOAPHandler that logs all the SOAP messages being sent over the
> wire. It's very similar to the one that ships as an example in the
> CXF distribution except that I'm logging to a log4j Logger.
>
> What's strange is that in one case the behavior of my SOAP service
> changes depending on whether the logging is enabled or not! (The
> SOAPHandler itself is enabled always, just the logging of the messages
> is enabled/disabled at runtime.) Even stranger, is that when the
> logging is enabled the service is working fine, but when the logging
> is disabled, the service errors with an unmarshalling error (see
> below).
>
> Logging a SOAP message shouldn't be affecting the parsing of a message
> in any way. Here's the relevant code:
>
> private void log(SOAPMessageContext smc)
> {
> if (!log.isTraceEnabled()) return;
>
> Boolean outbound =
> (Boolean)smc.get(MessageContext.MESSAGE_OUTBOUND_PROPERTY);
>
> SOAPMessage msg = smc.getMessage();
>
> try
> {
> if (outbound.booleanValue())
> { los.write(">\n".getBytes()); }
> else
> { los.write("<\n".getBytes()); }
> msg.writeTo(los);
> los.flush();
> }
> catch (Exception e)
> { log.error(e.getMessage(), e); }
> }
>
> It seems to me that either SOAPMessageContext.getMessage() or
> SOAPMessage.writeTo() must have some sort of sideaffect?!? Surely
> this can't be intended?
>
> Here's the error I'm getting when logging is NOT enabled (the code
> above returns on the initial if condition check):
>
> Oct 23, 2007 5:02:51 PM org.apache.cxf.phase.PhaseInterceptorChain
> doIntercept
> INFO: Interceptor has thrown exception, unwinding now
> org.apache.cxf.interceptor.Fault: Unmarshalling Error : Current state
> not START_ELEMENT or END_ELEMENT
> at
> org.apache.cxf.jaxb.JAXBEncoderDecoder.unmarshallArray(JAXBEncoderDeco
>der.java:443) at
> org.apache.cxf.jaxb.JAXBEncoderDecoder.unmarshall(JAXBEncoderDecoder.j
>ava:256) at
> org.apache.cxf.jaxb.io.DataReaderImpl.read(DataReaderImpl.java:40)
> at
> org.apache.cxf.interceptor.DocLiteralInInterceptor.getPara(DocLiteralI
>nInterceptor.java:235) at
> org.apache.cxf.interceptor.DocLiteralInInterceptor.handleMessage(DocLi
>teralInInterceptor.java:121) at
> org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseIntercepto
>rChain.java:207) at
> org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitia
>tionObserver.java:73) at
> org.apache.cxf.transport.servlet.ServletDestination.doMessage(ServletD
>estination.java:78) at
> org.apache.cxf.transport.servlet.ServletController.invokeDestination(S
>ervletController.java:231) at
> org.apache.cxf.transport.servlet.ServletController.invoke(ServletContr
>oller.java:139) at
> com.kelman.kws.v2.CXFServlet.invoke(CXFServlet.java:121) at
> com.kelman.kws.v2.CXFServlet.doPost(CXFServlet.java:92) at
> javax.servlet.http.HttpServlet.service(HttpServlet.java:709) at
> javax.servlet.http.HttpServlet.service(HttpServlet.java:802) at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Appli
>cationFilterChain.java:252) at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFi
>lterChain.java:173) at
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperVa
>lve.java:213) at
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextVa
>lve.java:178) at
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.ja
>va:126) at
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.ja
>va:105) at
> org.apache.catalina.valves.FastCommonAccessLogValve.invoke(FastCommonA
>ccessLogValve.java:495) at
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValv
>e.java:107) at
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java
>:148) at
> org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:
>869) at
> org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.pr
>ocessConnection(Http11BaseProtocol.java:664) at
> org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoi
>nt.java:527) at
> org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFoll
>owerWorkerThread.java:80) at
> org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPo
>ol.java:684) at java.lang.Thread.run(Thread.java:595)
> Caused by: java.lang.IllegalStateException: Current state not
> START_ELEMENT or END_ELEMENT
> at
> com.ctc.wstx.sr.BasicStreamReader.getName(BasicStreamReader.java:721)
> at
> org.apache.cxf.staxutils.DepthXMLStreamReader.getName(DepthXMLStreamRe
>ader.java:109) at
> org.apache.cxf.jaxb.JAXBEncoderDecoder.unmarshallArray(JAXBEncoderDeco
>der.java:426) ... 28 more
>
> Does anyone have any ideas on what is going on?
>
> Thanks,
> Corey
--
J. Daniel Kulp
Principal Engineer
IONA
P: 781-902-8727 C: 508-380-7194
daniel.kulp@iona.com
http://www.dankulp.com/blog
Re: Unintended Consequences...
Posted by Glen Mazza <gl...@verizon.net>.
Am Mittwoch, den 24.10.2007, 15:50 -0700 schrieb Yeroc:
> Glen Mazza-2 wrote:
> >
> > Am Mittwoch, den 24.10.2007, 14:36 -0700 schrieb Yeroc:
> >> All...
> >>
> >> I've got a very puzzling problem issue with CXF v2.0.1. I implemented a
> >> SOAPHandler that logs all the SOAP messages being sent over the wire.
> >> It's
> >> very similar to the one that ships as an example in the CXF distribution
> >> except that I'm logging to a log4j Logger.
> >>
> >
> > <snip/>
> >
> >> Does anyone have any ideas on what is going on?
> >
> > No...but Wireshark might be able to help you:
> > http://www.jroller.com/gmazza/date/20070918
> >
> > More debugging options:
> > http://cwiki.apache.org/CXF20DOC/debugging.html
> >
> >
>
> I'm not sure how Wireshark is going to help me in this case... or were you
> suggesting using Wireshark instead of the SOAPHandler to log SOAP messages?
> If so, that's not really the point of my message. The point is that by
> logging a message CXF's handling of that message is somehow different.
>
> Note that in both cases (with logging enabled or disabled) the SOAP message
> being sent over the wire from the SOAP client to the web service is
> identical.
Oops, I think I gave you bad information then. Sorry about that. I'm
not sure I can be of much help for you on this particular error.
Glen
Re: Unintended Consequences...
Posted by Yeroc <cp...@gmail.com>.
Glen,
Glen Mazza-2 wrote:
>
> Am Mittwoch, den 24.10.2007, 14:36 -0700 schrieb Yeroc:
>> All...
>>
>> I've got a very puzzling problem issue with CXF v2.0.1. I implemented a
>> SOAPHandler that logs all the SOAP messages being sent over the wire.
>> It's
>> very similar to the one that ships as an example in the CXF distribution
>> except that I'm logging to a log4j Logger.
>>
>
> <snip/>
>
>> Does anyone have any ideas on what is going on?
>
> No...but Wireshark might be able to help you:
> http://www.jroller.com/gmazza/date/20070918
>
> More debugging options:
> http://cwiki.apache.org/CXF20DOC/debugging.html
>
>
I'm not sure how Wireshark is going to help me in this case... or were you
suggesting using Wireshark instead of the SOAPHandler to log SOAP messages?
If so, that's not really the point of my message. The point is that by
logging a message CXF's handling of that message is somehow different.
Note that in both cases (with logging enabled or disabled) the SOAP message
being sent over the wire from the SOAP client to the web service is
identical. I'm not sure if I was clear that the logging is occurring in my
service on the server side, not at the client side... so it's something
internal to CXF that's different depending on whether logging is enabled or
not (not something that's visible externally via Wireshark.)
Corey
--
View this message in context: http://www.nabble.com/Unintended-Consequences...-tf4687206.html#a13396865
Sent from the cxf-user mailing list archive at Nabble.com.
Re: Unintended Consequences...
Posted by Glen Mazza <gl...@verizon.net>.
Am Mittwoch, den 24.10.2007, 14:36 -0700 schrieb Yeroc:
> All...
>
> I've got a very puzzling problem issue with CXF v2.0.1. I implemented a
> SOAPHandler that logs all the SOAP messages being sent over the wire. It's
> very similar to the one that ships as an example in the CXF distribution
> except that I'm logging to a log4j Logger.
>
<snip/>
> Does anyone have any ideas on what is going on?
No...but Wireshark might be able to help you:
http://www.jroller.com/gmazza/date/20070918
More debugging options:
http://cwiki.apache.org/CXF20DOC/debugging.html
>
> Thanks,
> Corey
RE: Unintended Consequences...
Posted by "Liu, Jervis" <jl...@iona.com>.
This indeed looks like a bug to me. I vaguely recalled that I once ran into a weird problem with SAAJ impl, which is that in some cases SOAPBody() wont be not properly initialized until SOAPMessage.writeTo() or some other similar methods are called. I guess what might happen is that CXF creates a STAX XMLStreamReader on top of a DOMSource which is in turn created from SOAPBody, this STAX wont have valid data to read until someone called SOAPMessage.writeTo(). Anyway, just a guess, could you please log a JIRA with your test case attached, I will take a deep look into this.
Thanks,
Jervis
> -----Original Message-----
> From: Yeroc [mailto:cplists@gmail.com]
> Sent: 2007?10?25? 5:37
> To: cxf-user@incubator.apache.org
> Subject: Unintended Consequences...
>
>
>
> All...
>
> I've got a very puzzling problem issue with CXF v2.0.1. I
> implemented a
> SOAPHandler that logs all the SOAP messages being sent over
> the wire. It's
> very similar to the one that ships as an example in the CXF
> distribution
> except that I'm logging to a log4j Logger.
>
> What's strange is that in one case the behavior of my SOAP
> service changes
> depending on whether the logging is enabled or not! (The
> SOAPHandler itself
> is enabled always, just the logging of the messages is
> enabled/disabled at
> runtime.) Even stranger, is that when the logging is enabled
> the service is
> working fine, but when the logging is disabled, the service
> errors with an
> unmarshalling error (see below).
>
> Logging a SOAP message shouldn't be affecting the parsing of
> a message in
> any way. Here's the relevant code:
>
> private void log(SOAPMessageContext smc)
> {
> if (!log.isTraceEnabled()) return;
>
> Boolean outbound =
> (Boolean)smc.get(MessageContext.MESSAGE_OUTBOUND_PROPERTY);
>
> SOAPMessage msg = smc.getMessage();
>
> try
> {
> if (outbound.booleanValue())
> { los.write(">\n".getBytes()); }
> else
> { los.write("<\n".getBytes()); }
> msg.writeTo(los);
> los.flush();
> }
> catch (Exception e)
> { log.error(e.getMessage(), e); }
> }
>
> It seems to me that either SOAPMessageContext.getMessage() or
> SOAPMessage.writeTo() must have some sort of sideaffect?!?
> Surely this
> can't be intended?
>
> Here's the error I'm getting when logging is NOT enabled (the
> code above
> returns on the initial if condition check):
>
> Oct 23, 2007 5:02:51 PM org.apache.cxf.phase.PhaseInterceptorChain
> doIntercept
> INFO: Interceptor has thrown exception, unwinding now
> org.apache.cxf.interceptor.Fault: Unmarshalling Error :
> Current state not
> START_ELEMENT or END_ELEMENT
> at
> org.apache.cxf.jaxb.JAXBEncoderDecoder.unmarshallArray(JAXBEnc
> oderDecoder.java:443)
> at
> org.apache.cxf.jaxb.JAXBEncoderDecoder.unmarshall(JAXBEncoderD
> ecoder.java:256)
> at
> org.apache.cxf.jaxb.io.DataReaderImpl.read(DataReaderImpl.java:40)
> at
> org.apache.cxf.interceptor.DocLiteralInInterceptor.getPara(Doc
> LiteralInInterceptor.java:235)
> at
> org.apache.cxf.interceptor.DocLiteralInInterceptor.handleMessa
> ge(DocLiteralInInterceptor.java:121)
> at
> org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseIn
> terceptorChain.java:207)
> at
> org.apache.cxf.transport.ChainInitiationObserver.onMessage(Cha
> inInitiationObserver.java:73)
> at
> org.apache.cxf.transport.servlet.ServletDestination.doMessage(
> ServletDestination.java:78)
> at
> org.apache.cxf.transport.servlet.ServletController.invokeDesti
> nation(ServletController.java:231)
> at
> org.apache.cxf.transport.servlet.ServletController.invoke(Serv
> letController.java:139)
> at com.kelman.kws.v2.CXFServlet.invoke(CXFServlet.java:121)
> at com.kelman.kws.v2.CXFServlet.doPost(CXFServlet.java:92)
> at
> javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
> at
> javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilt
> er(ApplicationFilterChain.java:252)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(Appli
> cationFilterChain.java:173)
> at
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardW
> rapperValve.java:213)
> at
> org.apache.catalina.core.StandardContextValve.invoke(StandardC
> ontextValve.java:178)
> at
> org.apache.catalina.core.StandardHostValve.invoke(StandardHost
> Valve.java:126)
> at
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReport
> Valve.java:105)
> at
> org.apache.catalina.valves.FastCommonAccessLogValve.invoke(Fas
> tCommonAccessLogValve.java:495)
> at
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEn
> gineValve.java:107)
> at
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdap
> ter.java:148)
> at
> org.apache.coyote.http11.Http11Processor.process(Http11Process
> or.java:869)
> at
> org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHa
> ndler.processConnection(Http11BaseProtocol.java:664)
> at
> org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolT
> cpEndpoint.java:527)
> at
> org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(Le
> aderFollowerWorkerThread.java:80)
> at
> org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(
> ThreadPool.java:684)
> at java.lang.Thread.run(Thread.java:595)
> Caused by: java.lang.IllegalStateException: Current state not
> START_ELEMENT
> or END_ELEMENT
> at
> com.ctc.wstx.sr.BasicStreamReader.getName(BasicStreamReader.ja
> va:721) at
> org.apache.cxf.staxutils.DepthXMLStreamReader.getName(DepthXML
> StreamReader.java:109)
> at
> org.apache.cxf.jaxb.JAXBEncoderDecoder.unmarshallArray(JAXBEnc
> oderDecoder.java:426)
> ... 28 more
>
> Does anyone have any ideas on what is going on?
>
> Thanks,
> Corey
> --
> View this message in context:
http://www.nabble.com/Unintended-Consequences...-tf4687206.html#a13395660
Sent from the cxf-user mailing list archive at Nabble.com.
----------------------------
IONA Technologies PLC (registered in Ireland)
Registered Number: 171387
Registered Address: The IONA Building, Shelbourne Road, Dublin 4, Ireland