[jira] [Updated] (QPIDJMS-473) NPE in AsyncCompletionTask - race condition

["Consultant Leon (Jira)" <ji...@apache.org>]

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

Consultant Leon updated QPIDJMS-473:
------------------------------------
    Attachment: fix_QPID-JMS-473_race_condition_where_SendCompletion_was_not_placed_on_asyncSendQueue_befo.patch

> NPE in AsyncCompletionTask - race condition
> -------------------------------------------
>
>                 Key: QPIDJMS-473
>                 URL: https://issues.apache.org/jira/browse/QPIDJMS-473
>             Project: Qpid JMS
>          Issue Type: Bug
>          Components: qpid-jms-client
>    Affects Versions: 0.45.0
>         Environment: Windows 10/64
> Dell 5530 8 cores (possibly explaining why the send thread completes faster than the thread recording the SendComplete on the queue?)
> java 8
>  
>            Reporter: Consultant Leon
>            Priority: Critical
>         Attachments: fix_QPID-JMS-473_race_condition_where_SendCompletion_was_not_placed_on_asyncSendQueue_befo.patch
>
>
> When I configure a completion listener and send 50 messages rapidly asynchronous I hit a race condition.
> Debugging the code proves that the envelope has not been placed on asyncSendQueue at the time the very first send completion arrives.
> This results in JmsSession line 1518 within the private AsyncCompletionTask class:
> SendCompletion completion = {color:#660e7a}asyncSendQueue{color}.peek();
> Returning *null* , as the asyncSendQueue does not yet contain the completion as it's still being populated in the other thread!
> The resulting null pointer exception is logged as a DEBUG message (!!! bad this should be a clear ERROR log with stack trace, it should never happen but if it does don't hide it this way !!!)
> Enabling debug logging then shows:
> 2019-09-19_03:53:00.526-DEBUG-[JmsSession [ID:811574d5-f47c-4dd3-82e9-c4aa4ce1d9b9:1:1] completion dispatcher]-Send completion task encounted unexpected error: null \{org.apache.qpid.jms.JmsSession:1567}
>  
> Another comment on the logging style, the exception should be logged not ex.getMessage() !! (you can't see from the log that it's an NPE this way).
>  
> Line 1567:
> {color:#660e7a}LOG{color}.debug({color:#008000}"Send completion task encounted unexpected error: {}"{color}, ex.getMessage());
> -->
> {color:#660e7a}LOG{color}.debug({color:#008000}"Send completion task encounted unexpected error"{color}, ex);
> (never assume getMessage() contains relevant data, log the stack unless 100% sure the exception is known and self descriptive but when are you 100% sure about such?)
> The problem is triggered by the design of the code at line 951:
>  
> {color:#000080}if {color}(envelope.isCompletionRequired()) {
>  {color:#660e7a}transactionContext{color}.send({color:#660e7a}connection{color}, envelope, {color:#000080}new {color}ProviderSynchronization() {
>  {color:#808000}@Override
> {color} {color:#000080}public void {color}onPendingSuccess() {
>  {color:#808080}// Provider accepted the send request so new we place the marker in
> {color}{color:#808080} // the queue so that it can be completed asynchronously.
> {color} {color:#660e7a}asyncSendQueue{color}.addLast({color:#000080}new {color}SendCompletion({color:#660e7a}envelope{color}, {color:#660e7a}listener{color}));
>  }
>  {color:#808000}@Override
> {color} {color:#000080}public void {color}onPendingFailure(ProviderException cause) {
>  {color:#808080}// Provider has rejected the send request so we will throw the
> {color}{color:#808080} // exception that is to follow so no completion will be needed.
> {color} }
>  });
> First the message is sent (and the sending is actually completed before the onPendingSuccess() is ever called!
> The design of this code should be changed to first record the outstanding send operation (so first do the asyncSendQueue.addLast) BEFORE sending the message.
> The method onPendingFailure can then implement logic to remove the SendCompletion from asyncSendQueue in the case the message could not be sent.
>  



--
This message was sent by Atlassian Jira
(v8.3.4#803005)

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org