[jira] [Created] (CXF-6930) Race-Condition with JMS-transport, LoggingInInterceptor spoils the payload while logging it

["Tobias Schöneberg (JIRA)" <ji...@apache.org>]

Tobias Schöneberg created CXF-6930:
--------------------------------------

             Summary: Race-Condition with JMS-transport, LoggingInInterceptor spoils the payload while logging it
                 Key: CXF-6930
                 URL: https://issues.apache.org/jira/browse/CXF-6930
             Project: CXF
          Issue Type: Bug
          Components: JMS
    Affects Versions: 3.1.6
            Reporter: Tobias Schöneberg


Hi,
I think we stumbled over a problem with cxf and the JMS-transport, 
if the {{LoggingFeature}} is used to log incoming response messages.

The problem is that sometimes, {{ClientProxyImpl.invoke(...)}} returns {{null}}, 
but from the logged message payload, it's clear that there is a not-null response payload coming from the sever.

I believe, I just figured out that it is in fact the logging of that very payload which causes {{ClientProxyImpl.invoke(...)}} to return {{null}}.

How?
There is a race between the actual "client thread" which waited for the server's response 
(i.e. {{exchange.wait()}} in {{JMSConduit.sendAndReceiveMessage(...)}} ) 
until notified by the ActiveMQ Session Task thread 
(i.e. {{exchange.notifyAll()}} in {{JMSConduit.processReplyMessage(...)}} )
one one side and the ActiveMQ Session Task thread itself on the other side.

Once the client thread is notified, it goes on with {{preProcessResult(...)}} and {{handleResponse(...)}} and somewhere in there the message's {{ByteArrayStream}} is read and the return object is created.

However, at the same time, back in the ActiveMQ thread, the interceptor chain is run. 

In my case it contains the {{LoggingInInterceptor}} which accesses the message's *same* {{ByteArrayInputStream}}, in the method {{LoggingInInterceptor.logInputStream(...)}} ).

Now, in {{logInputStream(...)}}, we have

{code:java}
IOUtils.copyAtLeast(bis, bos, limit == -1 ? Integer.MAX_VALUE : limit);
bos.flush();
bis = new SequenceInputStream(bos.getInputStream(), bis);

// restore the delegating input stream or the input stream
if (is instanceof DelegatingInputStream) {
    ((DelegatingInputStream)is).setInputStream(bis);
} else {
    message.setContent(InputStream.class, bis);
}
{code}

My problem happens if the client thread tries to read the message while "{{bis}}" was read, but not yet restored. During that time, "{{bis}}" is closed for the in the client thread and it will skip over it (or throw an Exception, based on its config).

My current best and maybe naive guess on how to solve this is to change the method {{JMSConduit.processReplyMessage(...)}} 
and execute the if-block around {{exchange.notifyAll();}} only after the if-block around {{incomingObserver.onMessage(exchange.getInMessage());}}

WDYT?

Best reagards
Tobias



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)