Interceptors and Logging

The CXF architecture provides us with interceptors – or the ability to intercept outgoing request and responses. One useful scenario could be logging. CXF in this case has stayed one step ahead and already built custom Log Interceptors.
I decided to add logging capabilities to my client. I used the code for CXF client from my previous post with some modifications:

public static void simpleExecution() {
 final String endpointAddress = "http://localhost:8080/WithSpring/services/echo";
  
 JaxWsProxyFactoryBean factory = new JaxWsProxyFactoryBean();
 factory.setServiceClass(IEcho.class); //the service SEI
 factory.setAddress(endpointAddress);

        //outputs the received message to the logger  
 factory.getInInterceptors().add(new LoggingInInterceptor());

       //outputs the sent message to the logger
 factory.getOutInterceptors().add(new LoggingOutInterceptor()); 

 IEcho client = (IEcho) factory.create();
  
 String reply = client.echoHi("Dude");
 System.out.println("Server said: " + reply);
}

In the code we have added only two lines. The JaxWsProxyFactoryBean is a factory for creating JAX-WS proxies. In its hierarchy are present two CopyOnWriteArrayList instances for holding both request and response associated interceptors. If we were to run the code now:

1356 [main] DEBUG org.apache.cxf.endpoint.ClientImpl  - set requestContext to m
essage be{java.lang.reflect.Method=public abstract java.lang.String com.code.fir
st.ws.server.IEcho.echoHi(java.lang.String), org.apache.cxf.jaxws.context.Wrappe
dMessageContext.SCOPES={org.apache.cxf.message.Message.ENDPOINT_ADDRESS=APPLICAT
ION}, org.apache.cxf.message.Message.ENDPOINT_ADDRESS=http://localhost:8080/With
Spring/services/echo}
 1356 [main] DEBUG org.apache.cxf.endpoint.ClientImpl  - ...
 1356 [main] DEBUG org.apache.cxf.endpoint.ClientImpl  - Interceptors contribute
d by client: [org.apache.cxf.interceptor.LoggingOutInterceptor@d1e7c2]
 1356 [main] DEBUG org.apache.cxf.endpoint.ClientImpl  - Interceptors contribute
d by endpoint: ...
 1356 [main] DEBUG org.apache.cxf.endpoint.ClientImpl  - Interceptors contribute
d by binding: ...
 1356 [main] DEBUG org.apache.cxf.endpoint.ClientImpl  - Interceptors contribute
d by databinding: []
...
 1371 [main] DEBUG org.apache.cxf.phase.PhaseInterceptorChain  - Adding intercep
tor org.apache.cxf.interceptor.LoggingOutInterceptor@d1e7c2 to phase pre-stream
...
 1683 [main] DEBUG org.apache.cxf.phase.PhaseInterceptorChain  - Chain org.apach
e.cxf.phase.PhaseInterceptorChain@33b121 was modified. Current flow:
  setup [PolicyOutInterceptor]
  pre-logical [HolderOutInterceptor, SwAOutInterceptor, WrapperClassOutIntercept
or, SoapHeaderOutFilterInterceptor]
  post-logical [SoapPreProtocolOutInterceptor]
  prepare-send [MessageSenderInterceptor]
  pre-stream [LoggingOutInterceptor, AttachmentOutInterceptor, StaxOutIntercepto
r]
  write [SoapOutInterceptor]
  marshal [WrappedOutInterceptor, BareOutInterceptor]
  write-ending [SoapOutEndingInterceptor]
  pre-stream-ending [StaxOutEndingInterceptor]
  prepare-send-ending [MessageSenderEndingInterceptor]
1698 [main] INFO  org.apache.cxf.services.IEchoService.IEchoPort.IEcho  - Outbo
und Message
---------------------------
ID: 1
Address: http://localhost:8080/WithSpring/services/echo
Encoding: UTF-8
Http-Method: POST
Content-Type: text/xml
Headers: {Accept=[*/*], SOAPAction=[""]}
Payload: <soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/"><
soap:Body><ns2:echoHi xmlns:ns2="http://server.ws.first.code.com/"><msg>Dude</ms
g></ns2:echoHi></soap:Body></soap:Envelope>
--------------------------------------

As seen from the logs:

1. Various modules of CXF add their own interceptors to the workflow. In fact if we look closely at the interceptor names, we can see that a major chunk of CXF functionality is implemented through interceptors.
2. The interceptors are grouped by phase. At various phases, the associated interceptors are executed.
3. The LoggingOutInterceptor is associated with the pre-stream phase and it logs the xml payload and HTTP headers.

Similarly when the response is returned from the server:

1730 [main] DEBUG org.apache.cxf.phase.PhaseInterceptorChain  - Chain org.apach
e.cxf.phase.PhaseInterceptorChain@c9630a was modified. Current flow:
  receive [PolicyInInterceptor, LoggingInInterceptor, AttachmentInInterceptor]
  post-stream [StaxInInterceptor]
  read [WSDLGetInterceptor, ReadHeadersInterceptor, SoapActionInInterceptor, Sta
rtBodyInterceptor]
  pre-protocol [MustUnderstandInterceptor]
  post-protocol [CheckFaultInterceptor, JAXBAttachmentSchemaValidationHack]
  unmarshal [DocLiteralInInterceptor, SoapHeaderInterceptor]
  post-logical [WrapperClassInInterceptor]
  pre-invoke [SwAInInterceptor, HolderInInterceptor, PolicyVerificationInInterce
ptor]

 1730 [main] DEBUG org.apache.cxf.phase.PhaseInterceptorChain  - Invoking handle
Message on interceptor org.apache.cxf.interceptor.LoggingInInterceptor@1dddba
 1745 [main] INFO  org.apache.cxf.services.IEchoService.IEchoPort.IEcho  - Inbou
nd Message
----------------------------
ID: 1
Response-Code: 200
Encoding: UTF-8
Content-Type: text/xml;charset=UTF-8
Headers: {Content-Length=[220], content-type=[text/xml;charset=UTF-8], Date=[Thu
, 04 Apr 2013 13:52:50 GMT], Server=[Apache-Coyote/1.1]}
Payload: <soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/"><
soap:Body><ns2:echoHiResponse xmlns:ns2="http://server.ws.first.code.com/"><retu
rn>Hi  Dude</return></ns2:echoHiResponse></soap:Body></soap:Envelope>
--------------------------------------
...
 Server said: Hi  Dude

The XML that was marshaled and unmarshaled are both visible in the response. We can make it more readable by modifying the code:

//outputs the bytes of the message to the logger
LoggingInInterceptor loggingInInterceptor =  new LoggingInInterceptor();
loggingInInterceptor.setPrettyLogging(true);
factory.getInInterceptors().add(loggingInInterceptor);
  
//outputs the bytes of the message to the logger
LoggingOutInterceptor loggingOutInterceptor = new LoggingOutInterceptor();
loggingOutInterceptor.setPrettyLogging(true);
factory.getOutInterceptors().add(loggingOutInterceptor);

The setPrettyLogging method formats the xml content before logging. The same logs would now look like below:

1652 [main] INFO  org.apache.cxf.services.IEchoService.IEchoPort.IEcho  - Outbo
und Message
---------------------------
ID: 1
Address: http://localhost:8080/WithSpring/services/echo
Encoding: UTF-8
Http-Method: POST
Content-Type: text/xml
Headers: {Accept=[*/*], SOAPAction=[""]}
Payload: <?xml version="1.0" encoding="UTF-8"?>
<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
  <soap:Body>
    <ns2:echoHi xmlns:ns2="http://server.ws.first.code.com/">
      <msg>Dude</msg>
    </ns2:echoHi>
  </soap:Body>
</soap:Envelope>

--------------------------------------

 1714 [main] INFO  org.apache.cxf.services.IEchoService.IEchoPort.IEcho  - Inbou
nd Message
----------------------------
ID: 1
Response-Code: 200
Encoding: UTF-8
Content-Type: text/xml;charset=UTF-8
Headers: {Content-Length=[220], content-type=[text/xml;charset=UTF-8], Date=[Thu
, 04 Apr 2013 14:02:27 GMT], Server=[Apache-Coyote/1.1]}
Payload: <?xml version="1.0" encoding="UTF-8"?>
<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
  <soap:Body>
    <ns2:echoHiResponse xmlns:ns2="http://server.ws.first.code.com/">
      <return>Hi  Dude</return>
    </ns2:echoHiResponse>
  </soap:Body>
</soap:Envelope>

--------------------------------------

The same can also be achieved via Spring defined beans too:

<jaxws:client id="client" serviceClass="com.code.first.ws.server.IEcho"
 address="http://localhost:8080/WithSpring/services/echo">
 <jaxws:inInterceptors>
  <bean id="loggingInInterceptor" class="org.apache.cxf.interceptor.LoggingInInterceptor" >
   <property name="prettyLogging" value="true" />
  </bean>
 </jaxws:inInterceptors>
 <jaxws:outInterceptors>
  <bean id="loggingOutInterceptor" class="org.apache.cxf.interceptor.LoggingOutInterceptor" >
   <property name="prettyLogging" value="true" />
  </bean>
 </jaxws:outInterceptors>
</jaxws:client>

We can take advantage of Spring's inheritance technique (idea taken from here):

<bean id="abstractLoggingInterceptor" abstract="true">
 <property name="prettyLogging" value="true" />
</bean>

<jaxws:client id="client" serviceClass="com.code.first.ws.server.IEcho"
 address="http://localhost:8080/WithSpring/services/echo">
 <jaxws:inInterceptors>
  <bean id="loggingInInterceptor" class="org.apache.cxf.interceptor.LoggingInInterceptor"
   parent="abstractLoggingInterceptor" />
 </jaxws:inInterceptors>
 <jaxws:outInterceptors>
  <bean id="loggingOutInterceptor" class="org.apache.cxf.interceptor.LoggingOutInterceptor"
   parent="abstractLoggingInterceptor" />
 </jaxws:outInterceptors>
</jaxws:client>