JAX-WS fault changes in mtom service when logging is enabled through SOAPHandler

Question

I have a jax-ws service published in a standalone server application. This service uses mtom to receive documents

As advised in the answer to this question:

Tracing XML request/responses with JAX-WS

I use a handler for soap message logging for the service as below:

public boolean handleMessage(SOAPMessageContext smc){
    performLoggingActions(smc);
    return true;
}

The logger method is as below:

 private void performLoggingActions(SOAPMessageContext smc) {
   ByteArrayOutputStream bout = null;
   try {
       Boolean isOutBound = (Boolean) smc.get(MessageContext.MESSAGE_OUTBOUND_PROPERTY);
       SOAPMessage message = smc.getMessage();
       //More stuff
    } catch (Exception e) {
        logger.error(String.format("Error in logSoapMessage! Error: %s ", e.getMessage()), e);
    } finally {
        IOUtils.closeQuietly(bout);
    }

}

When client sends a valid request, there is no problem in logging. Everything is logged as expected.

However, if I send an invalid content id in request via SOAP UI, the logging fails in line SOAPMessage message = smc.getMessage(); and I have the below error:

Error in logSoapMessage! Error: No such MIME Part: Part=5 
java.lang.IllegalStateException: No such MIME Part: Part=5
    at com.sun.xml.internal.org.jvnet.mimepull.DataHead.read(DataHead.java:138)
    at com.sun.xml.internal.org.jvnet.mimepull.MIMEPart.read(MIMEPart.java:85)

The problem is, when this occurs, the message does not propogate to service level and the service responds to the client with below fault:

<S:Envelope xmlns:S="http://schemas.xmlsoap.org/soap/envelope/">
   <S:Body>
      <S:Fault xmlns:ns4="http://www.w3.org/2003/05/soap-envelope">
         <faultcode>S:Server</faultcode>
         <faultstring>unexpected XML tag. expected: somenamespace but found: {http://www.w3.org/2004/08/xop/include}Include</faultstring>
      </S:Fault>
   </S:Body>
</S:Envelope>

When I disable soap logging and send a fault request, the message is propagated to service level, to the @WebService annotated class, and I receive a similar expection when trying to read the mtom content. However, in that case the error is reflected in the response as fault string:

 <S:Envelope xmlns:S="http://schemas.xmlsoap.org/soap/envelope/">
   <S:Body>
      <S:Fault xmlns:ns4="http://www.w3.org/2003/05/soap-envelope">
         <faultcode>S:Server</faultcode>
         <faultstring>No such MIME Part: Part=5</faultstring>
      </S:Fault>
   </S:Body>
</S:Envelope>

I would expect the same fault regardless of the existence of the logging handler.

As you can see, I am catching all exceptions in logging handler but the service response changes according to the existence of the logging handler.

I am doing something wrong? My requirement is getting the same fault with and without logging handler.

Regards

EDIT : Entire stack trace of the error added:

Error in logSoapMessage! Error: No such MIME Part: Part=5 
java.lang.IllegalStateException: No such MIME Part: Part=5
    at com.sun.xml.internal.org.jvnet.mimepull.DataHead.read(DataHead.java:138)
    at com.sun.xml.internal.org.jvnet.mimepull.MIMEPart.read(MIMEPart.java:85)
    at com.sun.xml.internal.ws.encoding.MIMEPartStreamingDataHandler$StreamingDataSource.getInputStream(MIMEPartStreamingDataHandler.java:98)
    at com.sun.xml.internal.org.jvnet.staxex.Base64Data.get(Base64Data.java:315)
    at com.sun.xml.internal.org.jvnet.staxex.Base64Data.length(Base64Data.java:357)
    at com.sun.xml.internal.ws.encoding.MtomCodec$MtomXMLStreamReaderEx.getTextCharacters(MtomCodec.java:533)
    at com.sun.istack.internal.XMLStreamReaderToContentHandler.handleCharacters(XMLStreamReaderToContentHandler.java:244)
    at com.sun.istack.internal.XMLStreamReaderToContentHandler.bridge(XMLStreamReaderToContentHandler.java:155)
    at com.sun.xml.internal.ws.message.stream.StreamMessage.writePayloadTo(StreamMessage.java:375)
    at com.sun.xml.internal.ws.message.stream.StreamMessage.writeTo(StreamMessage.java:460)
    at com.sun.xml.internal.ws.message.AbstractMessageImpl.readAsSOAPMessage(AbstractMessageImpl.java:196)
    at com.sun.xml.internal.ws.handler.SOAPMessageContextImpl.getMessage(SOAPMessageContextImpl.java:82)
    at com.ibtech.smg.esb.jaxws.handler.JAXWSSOAPLoggingHandler.performLoggingActions(JAXWSSOAPLoggingHandler.java:54)
    at com.ibtech.smg.esb.jaxws.handler.JAXWSSOAPLoggingHandler.handleMessage(JAXWSSOAPLoggingHandler.java:36)
    at com.ibtech.smg.esb.jaxws.handler.JAXWSSOAPLoggingHandler.handleMessage(JAXWSSOAPLoggingHandler.java:1)
    at com.sun.xml.internal.ws.handler.HandlerProcessor.callHandleMessage(HandlerProcessor.java:295)
    at com.sun.xml.internal.ws.handler.HandlerProcessor.callHandlersRequest(HandlerProcessor.java:138)
    at com.sun.xml.internal.ws.handler.ServerSOAPHandlerTube.callHandlersOnRequest(ServerSOAPHandlerTube.java:136)
    at com.sun.xml.internal.ws.handler.HandlerTube.processRequest(HandlerTube.java:118)
    at com.sun.xml.internal.ws.api.pipe.Fiber.__doRun(Fiber.java:639)
    at com.sun.xml.internal.ws.api.pipe.Fiber._doRun(Fiber.java:598)
    at com.sun.xml.internal.ws.api.pipe.Fiber.doRun(Fiber.java:583)
    at com.sun.xml.internal.ws.api.pipe.Fiber.runSync(Fiber.java:480)
    at com.sun.xml.internal.ws.server.WSEndpointImpl$2.process(WSEndpointImpl.java:312)
    at com.sun.xml.internal.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdapter.java:606)
    at com.sun.xml.internal.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:257)
    at com.sun.xml.internal.ws.transport.http.server.WSHttpHandler.handleExchange(WSHttpHandler.java:108)
    at com.sun.xml.internal.ws.transport.http.server.WSHttpHandler.handle(WSHttpHandler.java:93)
    at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:90)
    at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:96)
    at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:93)
    at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:690)
    at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:90)
    at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:662)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1157)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:627)
    at java.lang.Thread.run(Thread.java:809)

Answer 1

Could you please paste the entire stack trace and the code in your SOAP handler? Is this line getting printed in your logs?
logger.error(String.format("Error in logSoapMessage! Error: %s ", e.getMessage()), e);