[
https://issues.apache.org/jira/browse/QPID-4731?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13633936#comment-13633936
]
Keith Wall edited comment on QPID-4731 at 4/17/13 10:21 AM:
------------------------------------------------------------
There were circumstances where this defect could cause a stack trace. For
completeness I will describe this here.
In a scenario where the Broker has no other queues defined, if, following the
failed attempt to deregister the topic subscriber's temporary queue further
messages are enqueued, the following stack trace results and the client's
connection is abruptly closed.
This occurs because ReferenceCountingExecutorService has shutdown the
ThreadPoolExecutor (as no-one remains using it). The erroneous enqueue tries
to run a deliverAsync using the shutdown executor. This is rightfully rejected
with the REE.
There is no further work required to address this aspect. The changes made for
this Jira and QPID-3997 (the belt and braces) are sufficient.
{noformat}
IoReceiver - /127.0.0.1:54939 2013-04-17 10:43:18,803 ERROR
[qpid.server.protocol.AMQProtocolEngine] Unexpected exception when processing
datablock
java.util.concurrent.RejectedExecutionException
at
java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:1768)
at
java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:767)
at
java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:658)
at
org.apache.qpid.server.queue.QueueRunner.execute(QueueRunner.java:118)
at
org.apache.qpid.server.queue.SimpleAMQQueue.deliverAsync(SimpleAMQQueue.java:1530)
at
org.apache.qpid.server.queue.SimpleAMQQueue.enqueue(SimpleAMQQueue.java:718)
at
org.apache.qpid.server.AMQChannel$MessageDeliveryAction.postCommit(AMQChannel.java:1190)
at
org.apache.qpid.server.AMQChannel$AsyncCommand.complete(AMQChannel.java:1583)
at org.apache.qpid.server.AMQChannel.sync(AMQChannel.java:1553)
at
org.apache.qpid.server.AMQChannel.receivedComplete(AMQChannel.java:221)
at
org.apache.qpid.server.protocol.AMQProtocolEngine.receiveComplete(AMQProtocolEngine.java:267)
at
org.apache.qpid.server.protocol.AMQProtocolEngine.received(AMQProtocolEngine.java:250)
at
org.apache.qpid.server.protocol.AMQProtocolEngine.received(AMQProtocolEngine.java:81)
at
org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:118)
at
org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:37)
at
org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:161)
at java.lang.Thread.run(Thread.java:662)
{noformat}
was (Author: k-wall):
There were circumstances where this defect could cause a stack trace. For
completeness I will describe this here.
In a scenario where the Broker has no other queues defined, if, following the
failed attempt to deregister the topic subscriber's temporary queue further
messages are enqueued, the following stack trace results and the client's
connection is abruptly closed.
This occurs because ReferenceCountingExecutorService has shutdown the
ThreadPoolExecutor (as no-one remains using it). The erroneous enqueue tries
to run a deliverAsync using the shutdown executor. This is rightfully rejected
with the REE.
There is no further work required to address this aspect - the changes made for
this Jira and QPID-3997 (the belt and braces) are sufficient.
{noformat}
IoReceiver - /127.0.0.1:54939 2013-04-17 10:43:18,803 ERROR
[qpid.server.protocol.AMQProtocolEngine] Unexpected exception when processing
datablock
java.util.concurrent.RejectedExecutionException
at
java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:1768)
at
java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:767)
at
java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:658)
at
org.apache.qpid.server.queue.QueueRunner.execute(QueueRunner.java:118)
at
org.apache.qpid.server.queue.SimpleAMQQueue.deliverAsync(SimpleAMQQueue.java:1530)
at
org.apache.qpid.server.queue.SimpleAMQQueue.enqueue(SimpleAMQQueue.java:718)
at
org.apache.qpid.server.AMQChannel$MessageDeliveryAction.postCommit(AMQChannel.java:1190)
at
org.apache.qpid.server.AMQChannel$AsyncCommand.complete(AMQChannel.java:1583)
at org.apache.qpid.server.AMQChannel.sync(AMQChannel.java:1553)
at
org.apache.qpid.server.AMQChannel.receivedComplete(AMQChannel.java:221)
at
org.apache.qpid.server.protocol.AMQProtocolEngine.receiveComplete(AMQProtocolEngine.java:267)
at
org.apache.qpid.server.protocol.AMQProtocolEngine.received(AMQProtocolEngine.java:250)
at
org.apache.qpid.server.protocol.AMQProtocolEngine.received(AMQProtocolEngine.java:81)
at
org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:118)
at
org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:37)
at
org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:161)
at java.lang.Thread.run(Thread.java:662)
{noformat}
> Java Broker: topic subscription with selector bug can silently prevent
> temporary queue deletion
> -----------------------------------------------------------------------------------------------
>
> Key: QPID-4731
> URL: https://issues.apache.org/jira/browse/QPID-4731
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker
> Affects Versions: 0.6, 0.8, 0.10, 0.12, 0.14, 0.16, 0.18, 0.20
> Reporter: Philip Harvey
> Assignee: Philip Harvey
>
> When JMS selectors are used with topics, the attempt to deregister the topic
> subscriber's temporary queue can silently fail. This leaves the queue bound
> to the exchange, thereby allowing messages to continue being sent to it.
> This is shown in the following log excerpts from a v0.5 Broker:
> Initial set-up of topic with selector:
> {noformat}
> 2013-04-02 04:11:51,947 INFO [pool-1-thread-22]
> rawloggers.Log4jMessageLogger (Log4jMessageLogger.java:69) - MESSAGE
> [con:199(xxxxx@/yyy.yyy.yyy.yyy:45309/ZZZ)/ch:1]
> [vh(/ZZZ)/qu(tmp_yyy.yyy.yyy.yyy45309_2)] QUE-1001 : Create : Owner: xxx
> AutoDelete Transient
> 2013-04-02 04:11:51,949 INFO [pool-1-thread-22]
> rawloggers.Log4jMessageLogger (Log4jMessageLogger.java:69) - MESSAGE
> [con:199(xxxxx@/yyy.yyy.yyy.yyy:45309/ZZZ)/ch:1]
> [vh(/ZZZ)/ex(direct/<<default>>)/qu(tmp_yyy.yyy.yyy.yyy45309_2)/rk(tmp_yyy.yyy.yyy.yyy45309_2)]
> BND-1001 : Create
> 2013-04-02 04:11:51,957 INFO [pool-1-thread-23]
> rawloggers.Log4jMessageLogger (Log4jMessageLogger.java:69) - MESSAGE
> [con:199(xxxxx@/yyy.yyy.yyy.yyy:45309/ZZZ)/ch:1]
> [vh(/ZZZ)/ex(topic/amq.topic)/qu(tmp_yyy.yyy.yyy.yyy45309_2)/rk(XXX_Topic)]
> BND-1001 : Create : Arguments : {x-filter-jms-selector=[LONG_STRING:
> XXX_GROUP='xxxxx']}
> 2013-04-02 04:11:51,977 INFO [pool-1-thread-15]
> rawloggers.Log4jMessageLogger (Log4jMessageLogger.java:69) - MESSAGE
> [con:199(xxxxx@/yyy.yyy.yyy.yyy:45309/ZZZ)/ch:1]
> [sub:4,117(vh(/ZZZ)/qu(tmp_yyy.yyy.yyy.yyy45309_2)] SUB-1001 : Create :
> Arguments : JMSSelector(XXX_GROUP='xxxxx')
> 2013-04-02 14:14:02,663 INFO [pool-1-thread-30] queue.AMQQueueMBean
> (AMQQueueMBean.java:336) - QUEUE_DEPTH_ALERT On Queue
> tmp_yyy.yyy.yyy.yyy45309_2 - 4137Kb : Maximum queue depth threshold (4136Kb)
> breached.
> {noformat}
> Subsequent topic consumer close:
> {noformat}
> 2013-04-02 23:59:21,538 INFO [pool-1-thread-23]
> rawloggers.Log4jMessageLogger (Log4jMessageLogger.java:69) - MESSAGE
> [con:199(xxxxx@/yyy.yyy.yyy.yyy:45309/ZZZ)]
> [sub:4,117(vh(/ZZZ)/qu(tmp_yyy.yyy.yyy.yyy45309_2)] SUB-1002 : Close
> 2013-04-02 23:59:21,538 INFO [pool-1-thread-23]
> rawloggers.Log4jMessageLogger (Log4jMessageLogger.java:69) - MESSAGE
> [con:199(xxxxx@/yyy.yyy.yyy.yyy:45309/ZZZ)]
> [vh(/ZZZ)/ex(topic/amq.topic)/qu(tmp_yyy.yyy.yyy.yyy45309_2)/rk(XXX_Topic)]
> BND-1002 : Deleted
> 2013-04-02 23:59:21,538 INFO [pool-1-thread-23]
> rawloggers.Log4jMessageLogger (Log4jMessageLogger.java:69) - MESSAGE
> [con:199(xxxxx@/yyy.yyy.yyy.yyy:45309/ZZZ)]
> [vh(/ZZZ)/ex(direct/<<default>>)/qu(tmp_yyy.yyy.yyy.yyy45309_2)/rk(tmp_yyy.yyy.yyy.yyy45309_2)]
> BND-1002 : Deleted
> 2013-04-02 23:59:21,538 INFO [pool-1-thread-23]
> rawloggers.Log4jMessageLogger (Log4jMessageLogger.java:69) - MESSAGE
> [con:199(xxxxx@/yyy.yyy.yyy.yyy:45309/ZZZ)]
> [vh(/ZZZ)/qu(tmp_yyy.yyy.yyy.yyy45309_2)] QUE-1002 : Deleted
> {noformat}
> Queue depth alerts continue even though the queue should have been deleted.
> Note that the depth is actually increasing, indicating that message are still
> being enqueued.
> {noformat}
> 2013-04-03 05:22:34,463 INFO [pool-1-thread-14] queue.AMQQueueMBean
> (AMQQueueMBean.java:336) - QUEUE_DEPTH_ALERT On Queue
> tmp_yyy.yyy.yyy.yyy45309_2 - 4136Kb : Maximum queue depth threshold (4136Kb)
> breached.
> 2013-04-03 05:23:08,343 INFO [pool-1-thread-11] queue.AMQQueueMBean
> (AMQQueueMBean.java:336) - QUEUE_DEPTH_ALERT On Queue
> tmp_yyy.yyy.yyy.yyy45309_2 - 8570Kb : Maximum queue depth threshold (4136Kb)
> breached.
> {noformat}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@qpid.apache.org
For additional commands, e-mail: dev-h...@qpid.apache.org
