ADFLogger JAX-WS SoapHandler to log request, reponse and faults

Lately I see a lot of ADF projects consuming SOAP web services. This is typically done by creating a JAX-WS Proxy in JDeveloper and invoking this proxy from java beans exposed through the Bean Data Control or through programmatic ADF Business Components. This post will show how to instrument your JAX-WS proxy so it can log the SOAP request, payload and potential fault to an ADFLogger. This can be a very valuable tool during development and when diagnosing production issues.

Let's start with the final result, the weblogic console when invoking a web service that returns a soap fault. The nice thing is that it not only logs the fault but also the request that caused it:

SOAP request and response logged when receiving SOAP fault

When you crank up the log level you can even see all requests and responses that complete successful. As I described earlier this also allows for performance analysis with the Log Analyzer. This breaks down your entire request and our LoggingSoapHandler times the milliseconds it took to invoke the web service.

Log Analyzer showing this web service call took 5 msecs

This magic is performed by a JAX-WS SoapHandler. It can be registered with a JAX-WS proxy and has access to the web service request and response messages. Handlers can even change these, but in this example all we do is logging to the ADFLogger. You can setup handlers when creating the web service proxy or by right clicking an existing one and changing its properties.

Add LoggingSoapHandler as a Handler on the JAX-WS Proxy

You can get the full source code for the com.redheap.soaplog.LoggingSoapHandler class so you can add it to your own project or library. The embedded documentation is rather elaborate but I'll also explain the most important bits here.

JAX-WS will invoke the handleMessage method when sending or receiving a message. We check if this is an outbound message (aka request) or an inbound message (aka response):

    public boolean handleMessage(final SOAPMessageContext context) {
        if (Boolean.TRUE.equals(context.get(MessageContext.MESSAGE_OUTBOUND_PROPERTY))) {
            handleRequest(context);
        } else {
            handleResponse(context);
        }
        return true; // return true to continue processing other handlers
    }

When the log levels are set to verbose, the handleRequest method will log the fact that a web service is being invoked including the end point URL and it will log the actual request payload. Regardless the log level it will also invoke ADFLogger#begin to start a performance timer so the time spent invoking the web service will show up in the log analyzer. Finally, it also adds the request payload as well as a timestamp to the SOAPMessageContext. More on this later.

The handleResponse method will stop the performance timer by invoking ADFLogger#end. When the log levels are set to verbose, it will log the response payload and get the starting timestamp from the SOAPMessageContext (which was put there by handleRequest) and calculate the time spent and log this to the normal ADFLogger.

When an error occurs, such as receiving a soap fault from the web service, the JAX-WS proxy will not invoke the handleMessage method but it will invoke handleFault. Similar to handleResponse we stop the timer and when being verbose log the time spent on invoking the web service. But the really nice thing it does is log the fault response payload as well as the original request payload at warning level. This is why handleMessage put the request itself in the SOAPMessageContext, so handleFault can get the request there. It is a method for sharing state between the different methods of the (stateless) handler. The result can be seen in the first screenshot of this post.

We also made sure each service and service operation uses a distinct ADFLogger. In this example we are invoking the divideTen operation on the MyTestService web service which means we are using the com.redheap.soaplog.LoggingSoapHandler.MyTestService.divideTen logger. Since log levels work like a hierarchy this allows you to set the default log level for all LoggingSoapHandlers at com.redheap.soaplog.LoggingSoapHandler, or you can override this for all operations of a specific service at com.redheap.soaplog.LoggingSoapHandler.SERVICENAME or use the full name of the logger to set it for a specific operation. This can prove to be very valuable in a production environment where you can enable very specific logging at runtime without overwhelming your log files.

As always you can download the full sample application or browse the subversion repository to look at the source code. All you really need is the single com.redheap.soaplog.LoggingSoapHandler class, but the workspace also includes a very simple JSF page to invoking a (local) web service that divides 10 by the given input. This was used to create the screenshots and entering 0 as an input will give a nice divide by zero soap fault for testing.

The workspace also includes the com.redheap.soaplog.Tester class to demonstrate the logger from a plain java program. You can simply run that class, but be sure to first run the com.redheap.soaplog.test.MyTestService service to ensure it is deployed to your local weblogic. Switch between the two run profiles in the project properties to set the verbosity of the logger when running the Tester.