Consultant Leon created QPIDJMS-473:
---------------------------------------
Summary: 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
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: [email protected]
For additional commands, e-mail: [email protected]
