Spring-ws reads the entier stream when logging set to debug [SWS-219]

[gregturn]

Vladimir Ritz Bossicard opened SWS-219 and commented

Spring-ws reads the entire message for logging purposes (when logging is set to DEBUG) and Axiom complains that it has nothing else to process:

DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher - MessageDispatcher with name 'testing-ws' received request [<soapenv:Envelope xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"><ns1:echoRequest xmlns:ns1="http://localhost:8080/testing-ws/services/echo">Hello</ns1:echoRequest></soapenv:Body></soapenv:Envelope>]
DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher - Endpoint mapping [org.springframework.ws.soap.server.endpoint.mapping.SoapActionEndpointMapping@11415c8] maps request to endpoint [com.testing.system.infrastructure.ws.EchoEndpoint@1a220e6]
DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher - Testing endpoint adapter [org.springframework.ws.server.endpoint.adapter.MessageEndpointAdapter@11df164]
DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher - Testing endpoint adapter [org.springframework.ws.server.endpoint.adapter.PayloadEndpointAdapter@67c1a6]
DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher - Testing endpoint exception resolver [org.springframework.ws.soap.server.endpoint.SimpleSoapExceptionResolver@6279d]
WARN org.springframework.ws.soap.server.SoapMessageDispatcher - Endpoint invocation resulted in exception - responding with SOAP Fault
org.springframework.ws.soap.axiom.AxiomSoapBodyException: Could not access envelope: javax.xml.stream.XMLStreamException: ParseError at [row,col]:[1,322]
Message: already reached end document; nested exception is org.apache.axiom.om.OMException: javax.xml.stream.XMLStreamException: ParseError at [row,col]:[1,322]
Message: already reached end document
Caused by:
org.apache.axiom.om.OMException: javax.xml.stream.XMLStreamException: ParseError at [row,col]:[1,322]
Message: already reached end document
at org.apache.axiom.om.impl.builder.StAXOMBuilder.next(StAXOMBuilder.java:239)
at org.apache.axiom.om.impl.llom.OMElementImpl.buildNext(OMElementImpl.java:552)
at org.apache.axiom.om.impl.llom.OMElementImpl.getFirstOMChild(OMElementImpl.java:563)
at org.apache.axiom.om.impl.llom.OMElementImpl.getFirstElement(OMElementImpl.java:823)

Setting the log level to INFO solves the problem but the info is quite hard to find and very unpleasant during development/debugging

---

Affects: 1.0.1

Referenced from: commits fb73941

[gregturn]

Vladimir Ritz Bossicard commented

credit where credit is due.

Original post detailing the problem http://forum.springframework.org/showpost.php?p=145934&postcount=6

[gregturn]

Arjen Poutsma commented

The message dispatcher logs incoming and outgoing messages to the commons log in two ways:

• if TRACE is enabled, it logs the complete message contents on the TRACE level,
• if DEBUG is enabled, it logs the message payload name on the DEBUG level

the problem you experienced had to do with commons logging facade for log4j. Recently, log4j introduced the TRACE level, which commons had for some time now. So what the commons facade for log4j did in 1.0.4 whenever trace() was invoked, was pass it along at DEBUG level. The good news is that this is fixed in commons logging 1.1.

So upgrading to commons logging 1.1 solves your problem, because the message is not consumed anymore.

One thing I did change is the logging category for these messages to org.springframework.ws.server.MessageTracing for server-side logging and org.springframework.ws.client.MessageTracing for client-side logging. This makes it easier to enable/disable the log without getting rid of the standard MessageDispatcher messages.

[gregturn]

Arjen Poutsma commented

Closing 1.0.2 issues.