[SWS-764] SoapEnvelopeLoggingInterceptor logging only partial request/response when Axis SAAJ API is used along with Xalan 2.7.1 and log4j 1.2.16 (using %m option) Created: 16/Apr/12  Updated: 04/May/12  Resolved: 02/May/12

Status: Closed
Project: Spring Web Services
Component/s: Core
Affects Version/s: 2.0.2
Fix Version/s: 2.0.5

Type: Defect Priority: Minor
Reporter: Mahesh Kandpal Assignee: Arjen Poutsma
Resolution: Invalid Votes: 0
Labels: interceptor, logging
Remaining Estimate: 2d 4.5h
Time Spent: Not Specified
Original Estimate: 2d 4.5h
Environment:

Tomcat 6.0.14, Log4j 1.2.16, JDK 1.5.0_19, Xalan 2.7.1


Attachments: File holiday.war     Text File log4j.properties     XML File pom.xml    

 Description   

Excerpt of Catalina log:

Apr 16, 2012 3:33:33 PM org.apache.catalina.core.ApplicationContext log
INFO: Initializing Spring FrameworkServlet 'spring-ws'
2012-04-16 15:33:33,803 INFO [transport.http.MessageDispatcherServlet] - FrameworkServlet 'spring-ws': initialization started
2012-04-16 15:33:33,991 INFO [context.support.XmlWebApplicationContext] - Refreshing WebApplicationContext for namespace 'spring-ws-servlet': startup date [Mon Apr 16 15:33:33 IST 2012]; root of context hierarchy
2012-04-16 15:33:34,756 INFO [factory.xml.XmlBeanDefinitionReader] - Loading XML bean definitions from ServletContext resource [/WEB-INF/spring-ws-servlet.xml]
2012-04-16 15:33:39,428 INFO [addressing.server.AnnotationActionEndpointMapping] - Supporting [WS-Addressing August 2004, WS-Addressing 1.0]
2012-04-16 15:33:39,568 INFO [factory.support.DefaultListableBeanFactory] - Pre-instantiating singletons in org.s[email protected]188c838: defining beans [stubHumanResourceService,holidayEndpoint,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.ws.server.endpoint.mapping.PayloadRootAnnotationMethodEndpointMapping#0,org.springframework.ws.soap.server.endpoint.mapping.SoapActionAnnotationMethodEndpointMapping#0,org.springframework.ws.soap.addressing.server.AnnotationActionEndpointMapping#0,org.springframework.ws.server.endpoint.adapter.method.dom.DomPayloadMethodProcessor#0,org.springframework.ws.server.endpoint.adapter.method.SourcePayloadMethodProcessor#0,org.springframework.ws.server.endpoint.adapter.method.dom.JDomPayloadMethodProcessor#0,org.springframework.ws.server.endpoint.adapter.DefaultMethodEndpointAdapter#0,org.springframework.ws.soap.server.endpoint.interceptor.DelegatingSmartSoapEndpointInterceptor#0,org.springframework.ws.soap.server.endpoint.interceptor.PayloadRootSmartSoapEndpointInterceptor#0,org.springframework.xml.xsd.commons.CommonsXsdSchemaCollection#0,holiday]; root of factory hierarchy
2012-04-16 15:33:41,818 INFO [xsd.commons.CommonsXsdSchemaCollection] - Loaded ServletContext resource [/WEB-INF/holiday.xsd]
2012-04-16 15:33:43,130 INFO [soap.saaj.SaajSoapMessageFactory] - Creating SAAJ 1.3 MessageFactory with SOAP 1.1 Protocol
2012-04-16 15:33:43,209 INFO [transport.http.MessageDispatcherServlet] - FrameworkServlet 'spring-ws': initialization completed in 9406 ms
2012-04-16 15:33:44,990 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Request: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas">
   <soapenv:Header/>
   <soapenv:Body>
      <sch:HolidayRequest>
         <sch:Holiday>
            <sch:StartDate>2006-03-03
2012-04-16 15:33:45,224 INFO [hr.service.StubHumanResourceService] - Booking holiday from [03-Mar-06] to [07-Mar-06] for employee [Mahesh Kandpal]
2012-04-16 15:33:45,255 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Response: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas"><soapenv:Header/><soapenv:Body><sch:HolidayResponse xmlns:sch="http://mycompany.com/hr/schemas"><sch:Status xmlns:sch="http://mycompany.com/hr/schemas">Booked
2012-04-16 15:33:59,379 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Request: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas">
   <soapenv:Header/>
   <soapenv:Body>
      <sch:HolidayRequest>
         <sch:Holiday>
            <sch:StartDate>2006-03-03
2012-04-16 15:33:59,379 INFO [hr.service.StubHumanResourceService] - Booking holiday from [03-Mar-06] to [01-Mar-06] for employee [Mahesh Kandpal]
2012-04-16 15:33:59,379 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Response: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas"><soapenv:Header/><soapenv:Body><sch:HolidayResponse xmlns:sch="http://mycompany.com/hr/schemas"><sch:Status xmlns:sch="http://mycompany.com/hr/schemas">Not Booked
2012-04-16 15:34:16,845 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Request: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas">
   <soapenv:Header/>
   <soapenv:Body>
      <sch:HolidayRequest>
         <sch:Holiday>
            <sch:StartDate>2006-03-03
2012-04-16 15:34:16,845 INFO [hr.service.StubHumanResourceService] - Booking holiday from [03-Mar-06] to [07-Mar-06] for employee [Mahesh Kandpal]
2012-04-16 15:34:16,845 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Response: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas"><soapenv:Header/><soapenv:Body><sch:HolidayResponse xmlns:sch="http://mycompany.com/hr/schemas"><sch:Status xmlns:sch="http://mycompany.com/hr/schemas">Booked
2012-04-16 15:34:31,890 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Request: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas">
   <soapenv:Header/>
   <soapenv:Body>
      <sch:HolidayRequest>
         <sch:Holiday>
            <sch:StartDate>2006-03-03
2012-04-16 15:34:31,890 INFO [hr.service.StubHumanResourceService] - Booking holiday from [03-Mar-06] to [07-Mar-06] for employee [Mahesh Kandpal]
2012-04-16 15:34:31,890 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Response: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas"><soapenv:Header/><soapenv:Body><sch:HolidayResponse xmlns:sch="http://mycompany.com/hr/schemas"><sch:Status xmlns:sch="http://mycompany.com/hr/schemas">Booked

When I exclude Xalan from the axis-saaj-api dependency, it correctly displays the request/response in the log.

INFO: Initializing Spring FrameworkServlet 'spring-ws'
2012-04-16 16:16:49,950 INFO [transport.http.MessageDispatcherServlet] - FrameworkServlet 'spring-ws': initialization started
2012-04-16 16:16:49,997 INFO [context.support.XmlWebApplicationContext] - Refreshing WebApplicationContext for namespace 'spring-ws-servlet': startup date [Mon Apr 16 16:16:49 IST 2012]; root of context hierarchy
2012-04-16 16:16:50,168 INFO [factory.xml.XmlBeanDefinitionReader] - Loading XML bean definitions from ServletContext resource [/WEB-INF/spring-ws-servlet.xml]
2012-04-16 16:16:51,481 INFO [addressing.server.AnnotationActionEndpointMapping] - Supporting [WS-Addressing August 2004, WS-Addressing 1.0]
2012-04-16 16:16:51,512 INFO [factory.support.DefaultListableBeanFactory] - Pre-instantiating singletons in org.s[email protected]1085e92: defining beans [stubHumanResourceService,holidayEndpoint,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.ws.server.endpoint.mapping.PayloadRootAnnotationMethodEndpointMapping#0,org.springframework.ws.soap.server.endpoint.mapping.SoapActionAnnotationMethodEndpointMapping#0,org.springframework.ws.soap.addressing.server.AnnotationActionEndpointMapping#0,org.springframework.ws.server.endpoint.adapter.method.dom.DomPayloadMethodProcessor#0,org.springframework.ws.server.endpoint.adapter.method.SourcePayloadMethodProcessor#0,org.springframework.ws.server.endpoint.adapter.method.dom.JDomPayloadMethodProcessor#0,org.springframework.ws.server.endpoint.adapter.DefaultMethodEndpointAdapter#0,org.springframework.ws.soap.server.endpoint.interceptor.DelegatingSmartSoapEndpointInterceptor#0,org.springframework.ws.soap.server.endpoint.interceptor.PayloadRootSmartSoapEndpointInterceptor#0,org.springframework.xml.xsd.commons.CommonsXsdSchemaCollection#0,holiday]; root of factory hierarchy
2012-04-16 16:16:52,231 INFO [xsd.commons.CommonsXsdSchemaCollection] - Loaded ServletContext resource [/WEB-INF/holiday.xsd]
2012-04-16 16:16:52,512 INFO [soap.saaj.SaajSoapMessageFactory] - Creating SAAJ 1.3 MessageFactory with SOAP 1.1 Protocol
2012-04-16 16:16:52,543 INFO [transport.http.MessageDispatcherServlet] - FrameworkServlet 'spring-ws': initialization completed in 2593 ms
2012-04-16 16:16:52,902 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Request: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas">
   <soapenv:Header/>
   <soapenv:Body>
      <sch:HolidayRequest>
         <sch:Holiday>
            <sch:StartDate>2006-03-03</sch:StartDate>
            <sch:EndDate>2006-03-07</sch:EndDate>
         </sch:Holiday>
         <sch:Employee>
            <sch:Number>67</sch:Number>
            <sch:FirstName>Mahesh</sch:FirstName>
            <sch:LastName>Kandpal</sch:LastName>
         </sch:Employee>
      </sch:HolidayRequest>
   </soapenv:Body>
</soapenv:Envelope>
2012-04-16 16:16:52,949 INFO [hr.service.StubHumanResourceService] - Booking holiday from [03-Mar-06] to [07-Mar-06] for employee [Mahesh Kandpal]
2012-04-16 16:16:52,980 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Response: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas"><soapenv:Header/><soapenv:Body><sch:HolidayResponse><sch:Status>Booked</sch:Status><sch:Duration>4</sch:Duration><sch:EmployeeNumber>67</sch:EmployeeNumber></sch:HolidayResponse></soapenv:Body></soapenv:Envelope>
2012-04-16 16:17:00,729 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Request: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas">
   <soapenv:Header/>
   <soapenv:Body>
      <sch:HolidayRequest>
         <sch:Holiday>
            <sch:StartDate>2006-03-03</sch:StartDate>
            <sch:EndDate>2006-03-01</sch:EndDate>
         </sch:Holiday>
         <sch:Employee>
            <sch:Number>67</sch:Number>
            <sch:FirstName>Mahesh</sch:FirstName>
            <sch:LastName>Kandpal</sch:LastName>
         </sch:Employee>
      </sch:HolidayRequest>
   </soapenv:Body>
</soapenv:Envelope>
2012-04-16 16:17:00,729 INFO [hr.service.StubHumanResourceService] - Booking holiday from [03-Mar-06] to [01-Mar-06] for employee [Mahesh Kandpal]
2012-04-16 16:17:00,729 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Response: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas"><soapenv:Header/><soapenv:Body><sch:HolidayResponse><sch:Status>Not Booked</sch:Status><sch:Duration>-2</sch:Duration><sch:EmployeeNumber>67</sch:EmployeeNumber></sch:HolidayResponse></soapenv:Body></soapenv:Envelope>
2012-04-16 16:17:12,039 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Request: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas">
   <soapenv:Header/>
   <soapenv:Body>
      <sch:HolidayRequest>
         <sch:Holiday>
            <sch:StartDate>2006-03-03</sch:StartDate>
            <sch:EndDate>2006-03-07</sch:EndDate>
         </sch:Holiday>
         <sch:Employee>
            <sch:Number>67</sch:Number>
            <sch:FirstName>Mahesh</sch:FirstName>
            <sch:LastName>Kandpal</sch:LastName>
         </sch:Employee>
      </sch:HolidayRequest>
   </soapenv:Body>
</soapenv:Envelope>
2012-04-16 16:17:12,070 INFO [hr.service.StubHumanResourceService] - Booking holiday from [03-Mar-06] to [07-Mar-06] for employee [Mahesh Kandpal]
2012-04-16 16:17:12,070 DEBUG [endpoint.interceptor.SoapEnvelopeLoggingInterceptor] - Response: <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:sch="http://mycompany.com/hr/schemas"><soapenv:Header/><soapenv:Body><sch:HolidayResponse><sch:Status>Booked</sch:Status><sch:Duration>4</sch:Duration><sch:EmployeeNumber>67</sch:EmployeeNumber></sch:HolidayResponse></soapenv:Body></soapenv:Envelope>

I had used Xalan 2.7.1 initially with the default Sun SAAJ API as I was facing some issues w.r.t Response Payload as mentioned somewhere in the WS documentation.

Please look into the same. I have included the POM, log4j.properties as well as the Xalan-free WAR so as to fit inside 10M limit.

Thanks & Regards
Mahesh



 Comments   
Comment by Mahesh Kandpal [ 16/Apr/12 ]

By mistake, I had put the wrong POM. There is change in dependency for spring-ws-core instead of spring-ws-test. I have tested using both with Xalan 2.7.1. Getting same results...

Comment by Arjen Poutsma [ 02/May/12 ]

It looks like this is an Axis SAAJ issue, and not a Spring-WS issue. Especially because you mention that excluding the Xerces dependency from the Axis SAAJ jars solves the issue.

Please comment if there is something we can do about this issue, but for now I will resolve it.

Comment by Arjen Poutsma [ 04/May/12 ]

Closing old issues

Generated at Tue Dec 12 02:44:30 UTC 2017 using JIRA 6.4.14#64029-sha1:ae256fe0fbb912241490ff1cecfb323ea0905ca5.