Uploaded image for project: 'Spring Web Services'
  1. Spring Web Services
  2. SWS-219

Spring-ws reads the entier stream when logging set to debug

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 1.0.1
    • Fix Version/s: 1.0.2
    • Component/s: Core
    • Labels:
      None
    • Environment:
      Tomcat 5.5, JDK 1.4.2, Axiom 1.2.5

      Description

      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 [<?xml version='1.0' encoding='UTF-8'?><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.springfram[email protected]11415c8] maps request to endpoint [[email protected]]
      DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher - Testing endpoint adapter [org.sp[email protected]11df164]
      DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher - Testing endpoint adapter [org.sp[email protected]67c1a6]
      DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher - Testing endpoint exception resolver [org.spri[email protected]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

        Activity

        Hide
        vbossica Vladimir Ritz Bossicard added a comment -

        credit where credit is due.

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

        Show
        vbossica Vladimir Ritz Bossicard added a comment - credit where credit is due. Original post detailing the problem http://forum.springframework.org/showpost.php?p=145934&postcount=6
        Hide
        arjen.poutsma Arjen Poutsma added a comment -

        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.

        Show
        arjen.poutsma Arjen Poutsma added a comment - 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.
        Hide
        arjen.poutsma Arjen Poutsma added a comment -

        Closing 1.0.2 issues.

        Show
        arjen.poutsma Arjen Poutsma added a comment - Closing 1.0.2 issues.

          People

          • Assignee:
            arjen.poutsma Arjen Poutsma
            Reporter:
            vbossica Vladimir Ritz Bossicard
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: