JAX-WS Logging – how to log JAX-WS messages with log4j or commons logging

There is this project I’m currently supporting, for the sake of example lets call it the Skynet – yeah like ‘Terminator the movie’ Skynet. Skynet is a few years old now and I chose that nickname for a reason – some team members believe that (due to the “complexity”) this project is becoming self-aware any day now. I’m sure you folks remember nuclear explosion scene from the movie after original Skynet got berserk? Anyway, our job is to make sure this final day doesn’t come too quickly. In order to do that, we wanted to trace messages our system was sending over the wire to other systems/services we use for integration. Skynet is using Spring factory to create client proxies. The code for this particular client looks like this:

I thought we were using CXF JAX-WS implementation under the hood so (routinely) I just dropped standard cxf.xml file to the classpath to turn message interceptors on:

But it turns out Skynet didn’t like my cxf.xml and XML messages did not show up. After a bit of digging we discovered that Skynet is using Sun’s jax-ws reference implementation, which may come from rt.jar (in java 1.6) or from external jar file usually called jaxws-rt.jar or jaxws-rt-version.number.jar. We decided we didn’t want to change implementation to CXF at that point as this would probably kill Skynet instantly. So now we’re stuck with this implementation and Google says that, the only way you can turn the logging facility on, is by passing this argument to JVM while starting up:

-Dcom.sun.xml.ws.transport.http.client.HttpTransportPipe.dump="true"

which is good, when you want all your data sent over the wire appear on STDOUT. But Skynet is sending too much XML’s for log files to hold up. Plus we don’t need them all there. Besides we want them to appear in other log files maintained by log4j. We want XML messages to appear in context of other non-XML logging messages, what’s the point of having business process logs scattered over two different files? Google didn’t help us much, so we came up with the idea to write our own logger. It’ll have ability to log to any subsystem you want (commons loggin, slf4j, log4j … you name it). We want to configure it so that messages from namespace http://skynet/forever appear in log files but we’re not interested in anything more. Sounds great! Lets do it. We found out that in JAX-WS you can plug your own processing tube to ‘tube processing subsystem’. Sounds geekey, I know. But in practice it works with similar fashion to servlet filtering mechanism. In servlet API ServletRequest comes in and every filter in filter chain can contribute its changes to this request (or response) or even stop processing if needed. Tubes works this way too… if you look at it from 1000ft… I think. Anyway In JAX-WS XML Message is pushed through series of tubes and if your tube lays along the way you get the chance to alter the Message, or in our case just log it. You can read more about this

here We based our implementation on examples from page above. The difference is that in those examples the tube is adding header to Messages and we just need to log our Message with log4j. We also used DumpTube class available in jaxws-rt.jar. First you need TubelineAssemblerFactory then you should tell jax-ws implementation where to look for it. You do that by placing special file in META-INF jar directory. This is TubelineAssemblerFactory:

package pl.touk.example;

import com.sun.xml.ws.api.pipe.TubelineAssemblerFactory;
import com.sun.xml.ws.api.pipe.TubelineAssembler;
import com.sun.xml.ws.api.BindingID;

public class ExampleTubelineAssemblerFactory extends TubelineAssemblerFactory {
    public TubelineAssembler doCreate(BindingID bindingID) {
        return new ExampleTubeAssembler();
    }
}

And then you need to make sure that file named:

com.sun.xml.ws.api.pipe.TubelineAssemblerFactory

with class name of your factory inside:

pl.touk.example.ExampleTubelineAssemblerFactory

goes to directory META-INF/service into your jar file. Then you need to write TublineAssembler which basically connects many tubes into one tubeline. You need to make sure your tube gets somewhere in this line. This is implementation we’ve got:

package pl.touk.example;

import com.sun.xml.ws.api.pipe.Tube;
import com.sun.xml.ws.api.pipe.ClientTubeAssemblerContext;
import com.sun.xml.ws.api.pipe.ServerTubeAssemblerContext;
import com.sun.xml.ws.api.pipe.TubelineAssembler;

public class ExampleTubeAssembler implements TubelineAssembler {

    public Tube createClient(ClientTubeAssemblerContext context) {
        Tube head = context.createTransportTube();
        // this is where you plug in your
        // custom logging tube
        head = new ExampleLoggingTube(head);
        head = context.createSecurityTube(head);
        head = context.createWsaTube(head);
        head = context.createClientMUTube(head);
        return context.createHandlerTube(head);
    }

    public Tube createServer(ServerTubeAssemblerContext context) {

        // we did not need custom tube here at server
        Tube head = context.getTerminalTube();
        head = context.createHandlerTube(head);
        head = context.createMonitoringTube(head);
        head = context.createServerMUTube(head);
        head = context.createWsaTube(head);
        head = context.createSecurityTube(head);
        return head;
    }

}

Last class is the logger itself. We used code from DumpTube implementation (which comes with jaxws-rt.jar) but modified it a bit:

package pl.touk.example;

import com.sun.xml.ws.api.pipe.helper.AbstractFilterTubeImpl;
import com.sun.xml.ws.api.pipe.TubeCloner;
import com.sun.xml.ws.api.pipe.Tube;
import com.sun.xml.ws.api.pipe.NextAction;
import com.sun.xml.ws.api.message.*;
import java.io.ByteArrayOutputStream;

import org.apache.log4j.Logger;

import javax.xml.stream.XMLOutputFactory;
import javax.xml.stream.XMLStreamException;
import javax.xml.stream.XMLStreamWriter;
import java.lang.reflect.Constructor;

public class ExampleLoggingTube extends AbstractFilterTubeImpl {

    // only for displaying information that message from particular URI gets to this logger
    // so that user knows what kind of messages she could
    // enable in log4j configuration file
    public static final Logger log = Logger.getLogger(ExampleLoggingTube.class);

    final XMLOutputFactory staxOut = XMLOutputFactory.newInstance();

    protected ExampleLoggingTube(Tube next) {
        super(next);
    }

    protected ExampleLoggingTube(AbstractFilterTubeImpl that, TubeCloner cloner) {
        super(that, cloner);
    }

    public ExampleLoggingTube copy(TubeCloner cloner) {
        return new ExampleLoggingTube(this, cloner);
    }

    @Override
    public NextAction processRequest(Packet request) {

        Message message = request.getMessage();
        logMessage(message);

        return super.processRequest(request);
    }

    public NextAction processResponse(Packet packet) {

        Message message = packet.getMessage();
        logMessage(message);

        return super.processResponse(packet);
    }

    private void logMessage(Message message){
        if (message == null) {
            log.info("Logger processing request message: null");
            return;
        }

        // extract message URI an log it with different logger so that user
        // sees that messages from this uri gets to this implementation
        // but it may be filtered out
        // and not shown due to log4 logging level settings
        String messageUri = extractMessageUri(message);
        log.info("Logger processing response for URI: " + messageUri);

        ByteArrayOutputStream outputStream = new ByteArrayOutputStream();
        try {
            XMLStreamWriter writer = staxOut.createXMLStreamWriter(outputStream);
            writer = createIndenter(writer);
            message.copy().writeTo(writer);
            writer.close();
            logByteOutputStream(messageUri, outputStream);
        } catch (XMLStreamException e) {
            log.error("Error during logging message in ExampleLoggingTube", e);
        }
    }

    private void logByteOutputStream(String messageUri, ByteArrayOutputStream outputStream) {
        if (outputStream.size() > 0) {
            String outputLog = new String(outputStream.toByteArray());
            StringBuffer buffer = new StringBuffer();
            buffer.append(messageUri);
            buffer.append(" : ");
            buffer.append(outputLog);

            logMessageToNamspaceAwareLogger(messageUri,buffer.toString());
        }
    }

    // log your message here to any logger you like, you can create
    // logger based on messageUri here or any other message/packet attribute
    // for that matter, then in log4j file you can choose which messages you
    // want to appear in log files
    protected void logMessageToNamspaceAwareLogger(String messageUri, String message){
            Logger log = Logger.getLogger(messageUri);
            log.debug(message);
    }

    private String extractMessageUri(Message message) {
        String messageUri = message.getPayloadNamespaceURI();
        if (messageUri == null || messageUri.length() == 0) {
            messageUri = "default";
        }
        return messageUri;
    }

    /**
     * Wraps {@link XMLStreamWriter} by an indentation engine if possible.
     *
     *

• We can do this only when we have

stax-utils.jar in the classpath. */ private XMLStreamWriter createIndenter(XMLStreamWriter writer) { try { Class clazz = getClass().getClassLoader().loadClass(“javanet.staxutils.IndentingXMLStreamWriter”); Constructor c = clazz.getConstructor(XMLStreamWriter.class); writer = (XMLStreamWriter) c.newInstance(writer); } catch (Exception e) { log.warn(“WARNING: put stax-utils.jar to the classpath to indent the dump output”); } return writer; } } I didn’t test this well enough to be sure, but I think this tube based logging should work with any jax-ws implementation. Drop me a line at lkc@touk.pl if you find this post useful or just leave your comments here.