Details
-
Bug
-
Status: Closed
-
Critical
-
Resolution: Fixed
-
0.45.0
-
None
-
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
Description
When a server does not offer support for the 'anonymous relay' capability, the client falls back to opening and closing links to satisfy send requests for anonymous producers (i.e JMSProducer instances, and MessageProducers created without a destination). The fallback mechanism does not currently account for use of a CompletionListener during the send, and so fails to notify it. It should be updated to handle usage of a CompletionListener.
============
Original Description:
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 = asyncSendQueue.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:
LOG.debug("Send completion task encounted unexpected error: {}", ex.getMessage());
-->
LOG.debug("Send completion task encounted unexpected error", 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:
if (envelope.isCompletionRequired()) {
transactionContext.send(connection, envelope, new ProviderSynchronization() {
@Override public void onPendingSuccess() {
// Provider accepted the send request so new we place the marker in // the queue so that it can be completed asynchronously. asyncSendQueue.addLast(new SendCompletion(envelope, listener));
}
@Override public void onPendingFailure(ProviderException cause) {
// Provider has rejected the send request so we will throw the // exception that is to follow so no completion will be needed. }
});
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.