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

["Sergey Beryozkin (JIRA)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/CXF-6930?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Sergey Beryozkin resolved CXF-6930.
-----------------------------------
       Resolution: Fixed
         Assignee: Daniel Kulp
    Fix Version/s: 3.1.8

> 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
>            Assignee: Daniel Kulp
>             Fix For: 3.1.8
>
>
> 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)