[
https://issues.apache.org/jira/browse/QPIDJMS-473?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Robbie Gemmell reassigned QPIDJMS-473:
--------------------------------------
Assignee: Robbie Gemmell
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 = {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.
was:
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.
Summary: failure handling CompletionListener when using fallback
anonymous producers (was: NPE in AsyncCompletionTask - race condition)
> failure handling CompletionListener when using fallback anonymous producers
> ---------------------------------------------------------------------------
>
> 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
> Assignee: Robbie Gemmell
> Priority: Critical
> Attachments:
> fix_QPID-JMS-473_race_condition_where_SendCompletion_was_not_placed_on_asyncSendQueue_befo.patch
>
>
> 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 = {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]
