How to log SOAP messages on client side?

Question

Good day. I'm learning how to write a connector to external SOAP RCP styled service. I'm using jaxws-maven-plugin plugin to generate Java classes from the WSDL file. And I'm using Spring to create the web service client bean:

@Configuration
public class StoreServiceConfig {

    @Bean
    public StoreWS storeWS() throws IOException {
        JaxWsPortProxyFactoryBean factoryBean = new JaxWsPortProxyFactoryBean();
        factoryBean.setServiceInterface(StoreWS.class);
        factoryBean.setWsdlDocumentUrl(new ClassPathResource("/wsdl/StoreWS.wsdl").getURL());
        factoryBean.setNamespaceUri("urn_store");
        factoryBean.setServiceName("StoreWSService");
        factoryBean.setEndpointAddress("https://10.34.45.82/storeservice/services/StoreWS");
        factoryBean.setUsername("testuser");
        factoryBean.setPassword("testpassword");
        factoryBean.afterPropertiesSet();
        return (StoreWS) factoryBean.getObject();
    }
}

To test the client I wrote a test class using JUnit. I call the client this way :

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration(classes = StoreServiceTestConfig.class)
public class StoreServiceImplTest {
    @Autowired
    private StoreWS storeWS;
    ...
    @Test
    public void testExecuteQuery() throws Exception {
        ...
        StoreResponseType response = storeWS.executeQuery(storeRequest);
        ...
    }
}

Now I need the test to log complete outgoing and incoming SOAP messages into a console. How to do that please? The easier way the better.

I found advices to use following system parameters but none of them work for me:

com.sun.xml.internal.ws.transport.http.client.HttpTransportPipe.dump=true
com.sun.xml.ws.transport.http.client.HttpTransportPipe.dump=true
com.sun.xml.ws.transport.local.LocalTransportPipe.dump=true
com.sun.xml.ws.transport.http.HttpAdapter.dump=true

I'm using Spring configuration classes (no XMLs) and the latest releases of all dependencies.

I'v found this answer but I don't know how to use it in my scenario.

Many thanks in advance! Vojtech

EDIT: My logback.xml looks like this but I still can't see any soap messages in the console:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="consoleAppender" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg %n
            </Pattern>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>DEBUG</level>
        </filter>
    </appender>
    <logger name="org.springframework.ws.client.MessageTracing">
        <level value="DEBUG" />
        <appender-ref ref="consoleAppender" />
    </logger>
    <logger name="org.springframework.ws.server.MessageTracing">
        <level value="DEBUG" />
        <appender-ref ref="consoleAppender" />
    </logger>
    <root>
        <level value="DEBUG" />
        <appender-ref ref="consoleAppender" />
    </root>
</configuration>

EDIT 2: pom.xml of the parent project specifies these dependencies:

<properties>
    <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
    <spring.version>4.1.2.RELEASE</spring.version>
    <spring-ws-core.version>2.2.0.RELEASE</spring-ws-core.version>
    <slf4j.version>1.7.7</slf4j.version>
    <logback.version>1.1.2</logback.version>
    <junit.version>4.12</junit.version>
    <commons-logging.version>1.1.1</commons-logging.version>
</properties>

<dependencyManagement>
    <dependencies>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-context</artifactId>
            <version>${spring.version}</version>
            <exclusions>
                <exclusion>
                    <groupId>commons-logging</groupId>
                    <artifactId>commons-logging</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-web</artifactId>
            <version>${spring.version}</version>
            <exclusions>
                <exclusion>
                    <groupId>commons-logging</groupId>
                    <artifactId>commons-logging</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <dependency>
            <groupId>org.springframework.ws</groupId>
            <artifactId>spring-ws-core</artifactId>
            <version>${spring-ws-core.version}</version>
            <exclusions>
                <exclusion>
                    <groupId>commons-logging</groupId>
                    <artifactId>commons-logging</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <!-- LOGGING -->
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>${slf4j.version}</version>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>jcl-over-slf4j</artifactId>
            <version>${slf4j.version}</version>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>log4j-over-slf4j</artifactId>
            <version>${slf4j.version}</version>
        </dependency>
        <dependency>
            <groupId>commons-logging</groupId>
            <artifactId>commons-logging</artifactId>
            <version>${commons-logging.version}</version>
        </dependency>
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>${logback.version}</version>
        </dependency>
        <!-- TESTING -->
        <dependency>
            <groupId>junit</groupId>
            <artifactId>junit</artifactId>
            <version>${junit.version}</version>
        </dependency>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-test</artifactId>
            <version>${spring.version}</version>
        </dependency>
    </dependencies>
</dependencyManagement>

pom.xml of module in which the test class is located depends on:

<dependencies>
    <dependency>
        <groupId>${project.groupId}</groupId>
        <artifactId>vinweb-connector-ws</artifactId>
    </dependency>
    <dependency>
        <groupId>${project.groupId}</groupId>
        <artifactId>vinweb-connector-api</artifactId>
    </dependency>
    <dependency>
        <groupId>org.springframework</groupId>
        <artifactId>spring-context</artifactId>
    </dependency>
    <!-- LOGGING -->
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
    </dependency>
    <dependency>
        <groupId>commons-logging</groupId>
        <artifactId>commons-logging</artifactId>
    </dependency>
    <!-- TESTING -->
    <dependency>
        <groupId>junit</groupId>
        <artifactId>junit</artifactId>
    </dependency>
    <dependency>
        <groupId>org.springframework</groupId>
        <artifactId>spring-test</artifactId>
    </dependency>
</dependencies>

EDIT 3: I'v added LoggingHandler class to my project:

package storeservice.log;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import javax.xml.namespace.QName;
import javax.xml.soap.MimeHeader;
import javax.xml.soap.MimeHeaders;
import javax.xml.soap.SOAPMessage;
import javax.xml.ws.handler.MessageContext;
import javax.xml.ws.handler.soap.SOAPHandler;
import javax.xml.ws.handler.soap.SOAPMessageContext;
import java.io.ByteArrayOutputStream;
import java.io.OutputStream;
import java.util.Collections;
import java.util.Iterator;
import java.util.Set;

@Component
public class LoggingHandler implements SOAPHandler<SOAPMessageContext> {

    private final Logger LOG = LoggerFactory.getLogger(LoggingHandler.class);

    @Override
    public Set<QName> getHeaders() {
        return Collections.emptySet();
    }

    @Override
    public boolean handleMessage(SOAPMessageContext context) {
        logMessage(context, "SOAP message : ");
        return true;
    }

    @Override
    public boolean handleFault(SOAPMessageContext context) {
        logMessage(context, "SOAP error : ");
        return true;
    }

    @Override
    public void close(MessageContext context) {
    }

    private void logMessage(SOAPMessageContext context, String type) {
        try {
            if(LOG.isDebugEnabled()) {
                Boolean outboundProperty = (Boolean) context.get(MessageContext.MESSAGE_OUTBOUND_PROPERTY);
                if(outboundProperty) {
                    LOG.debug("Outbound " + type);
                } else {
                    LOG.debug("Inbound " + type);
                }

                SOAPMessage message = context.getMessage();

                // Print out the MIME headers
                MimeHeaders headers = message.getMimeHeaders();
                Iterator<MimeHeader> headersIterator = headers.getAllHeaders();
                MimeHeader mimeHeader;
                LOG.debug("  Mime headers :");
                while(headersIterator.hasNext()) {
                    mimeHeader = headersIterator.next();
                    LOG.debug("    " + mimeHeader.getName() + " : " + mimeHeader.getValue());
                }

                // Print out the message body
                LOG.debug("  Message body :");
                try(OutputStream outStream = new ByteArrayOutputStream()) {
                    message.writeTo(outStream);
                    LOG.debug("    " + outStream.toString());
                }
            }
        } catch (Exception e){
            if(LOG.isErrorEnabled()) {
                LOG.error("Error logging SOAP message", e);
            }
        }
    }
}

And I use it to create the web service client bean:

@Configuration
public class StoreServiceConfig {

    @Autowired
    private LoggingHandler loggingHandler;

    @Bean
    public StoreWS storeWS() throws IOException {
        JaxWsPortProxyFactoryBean factoryBean = new JaxWsPortProxyFactoryBean();
        factoryBean.setServiceInterface(StoreWS.class);
        factoryBean.setWsdlDocumentUrl(new ClassPathResource("/wsdl/StoreWS.wsdl").getURL());
        factoryBean.setNamespaceUri("urn_store");
        factoryBean.setServiceName("StoreWSService");
        factoryBean.setEndpointAddress("https://10.34.45.82/storeservice/services/StoreWS");
        factoryBean.setUsername("testuser");
        factoryBean.setPassword("testpassword");

        factoryBean.setHandlerResolver(handlerResolver());

        factoryBean.afterPropertiesSet();
        return (StoreWS) factoryBean.getObject();
    }

    @Bean
    public HandlerResolver handlerResolver() {
        return new HandlerResolver() {
            @Override
            public List<Handler> getHandlerChain(PortInfo portInfo) {
                List<Handler> handlerChain = new ArrayList<>();
                handlerChain.add(loggingHandler);
                return handlerChain;
            }
        };
    }
}

The result is that SOAP messages are logged but response of calling storeWS.executeQuery is NULL:

StoreResponseType response = storeWS.executeQuery(storeRequest);

If I comment out following line then it starts work again and the response is assigned an object but no SOAP messages are logged:

// factoryBean.setHandlerResolver(handlerResolver());

I have found out that following line in class LoggingHandler causes that the response of calling the service is null:

SOAPMessage message = context.getMessage();

Answer 1

The answer you talk about seems to refer to CXF-based implementation of SOAP Client. In that sort of implementation, you have to add logging interceptors to endpoint. You can use some sort of implementation with Spring if you want, and you can configure everything without any XML, tell me if you are interested.

In your case, you can modify the log level of org.springframework.ws.server.MessageTracing to DEBUG if you want to see messages.

I hope this help you, and have a good day ;).

---

EDIT

After some research, it seems that logging configuration doesn't work with a JaxWsPortProxyFactoryBean. This topic on Spring forums talk about the same problem as yours. So, as suggested over there, you can create your own Message Handler, and your own HandlerResolver implementation to log your message. To test that solution, i use the Logging Handler logMessage code from docs.oracle.com, and I create a new HandlerChain implementation which add that LoggingHandler into handlerChain. Finally, I set that HandlerChain into the JaxWsPortProxyFactoryBean.

To be more concrete, here is your modified configuration :

@Configuration
public class StoreServiceConfig {

    @Bean
    public StoreWS storeWS() throws IOException {
      JaxWsPortProxyFactoryBean factoryBean = new JaxWsPortProxyFactoryBean();
      factoryBean.setServiceInterface(StoreWS.class);
      factoryBean.setWsdlDocumentUrl(new ClassPathResource("/wsdl/StoreWS.wsdl").getURL());
      factoryBean.setNamespaceUri("urn_store");
      factoryBean.setServiceName("StoreWSService");
      factoryBean.setEndpointAddress("https://10.34.45.82/storeservice/services/StoreWS");
      factoryBean.setUsername("testuser");
      factoryBean.setPassword("testpassword");

      factoryBean.setHandlerResolver(handlerResolver());

      factoryBean.afterPropertiesSet();
      return (StoreWS) factoryBean.getObject();
  }

  public HandlerResolver handlerResolver() {
    return new HandlerResolver() {

        public List<Handler> getHandlerChain(PortInfo portInfo) {
            List<Handler> handlerChain = new ArrayList<Handler>();
            handlerChain.add(new LoggingHandler());
            return handlerChain;
        }

    };
 }

}

and the LoggingHandler class :

public class LoggingHandler implements SOAPHandler<SOAPMessageContext> {

  private final org.slf4j.Logger LOG = LoggerFactory
        .getLogger("SOAPMessageLoggingHandler");

  public void close(MessageContext context) {
     }

  public boolean handleFault(SOAPMessageContext context) {
    logMessage(context, "SOAP Error is : ");
    return true;
  }

  public boolean handleMessage(SOAPMessageContext context) {
    logMessage(context, "SOAP Message is : ");
    return true;
  }

  public Set<QName> getHeaders() {
    return Collections.EMPTY_SET;
  }

  private boolean logMessage(MessageContext mc, String type) {
    try {
        if (LOG.isDebugEnabled()) {
            LOG.debug(type);
            SOAPMessage msg = ((SOAPMessageContext) mc)
                    .getMessage();

            // Print out the Mime Headers
            MimeHeaders mimeHeaders = msg.getMimeHeaders();
            Iterator mhIterator = mimeHeaders.getAllHeaders();
            MimeHeader mh;
            String header;
            LOG.debug("  Mime Headers:");
            while (mhIterator.hasNext()) {
                mh = (MimeHeader) mhIterator.next();
                header = new StringBuffer(" Name: ")
                        .append(mh.getName()).append(" Value: ")
                        .append(mh.getValue()).toString();
                LOG.debug(header);
            }

            LOG.debug(" SOAP Message: ");
            ByteArrayOutputStream baos = new ByteArrayOutputStream();
            msg.writeTo(baos);
            LOG.debug("   " + baos.toString());
            baos.close();
        }

        return true;
    } catch (Exception e) {
        if (LOG.isErrorEnabled()) {
            LOG.error("Error logging SOAP message",
                    e);
        }

        return false;
    }
  }
}

And finally, what that print into console with Logback for the request message ... :

    17:29:22 [main] DEBUG SOAPMessageLoggingHandler - SOAP Message is :  
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -   Mime Headers: 
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -  Name: Accept Value: text/xml, text/html
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -  Name: Content-Type Value: text/xml; charset=utf-8 
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -  Name: Content-Length Value: 246 
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -  SOAP Message:  
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -    <S:Envelope xmlns:S="http://schemas.xmlsoap.org/soap/envelope/" xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><S:Body><ns2:executeQuery xmlns:ns2="org.test"><arg0>test</arg0></ns2:executeQuery></S:Body></S:Envelope> 

... and for the response message :

    17:29:22 [main] DEBUG SOAPMessageLoggingHandler - SOAP Message is :  
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -   Mime Headers: 
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -  Name: Accept Value: text/xml, text/html
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -  Name: Content-Type Value: text/xml; charset=utf-8 
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -  Name: Content-Length Value: 266 
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -  SOAP Message:  
    17:29:22 [main] DEBUG SOAPMessageLoggingHandler -    <S:Envelope xmlns:S="http://schemas.xmlsoap.org/soap/envelope/" xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><S:Body><ns2:executeQueryResponse xmlns:ns2="org.test"><return>test</return></ns2:executeQueryResponse></S:Body></S:Envelope> 

It is less impacting than replace your Spring implementation with a CXF one, I think. I hope that answer will be more effective than my first one ^^.