[
https://issues.apache.org/jira/browse/ARTEMIS-4242?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Robbie Gemmell reopened ARTEMIS-4242:
-------------------------------------
> closing session with recent 'async acks' can lead to exceptions from apparent
> consumer cleanup race
> ---------------------------------------------------------------------------------------------------
>
> Key: ARTEMIS-4242
> URL: https://issues.apache.org/jira/browse/ARTEMIS-4242
> Project: ActiveMQ Artemis
> Issue Type: Bug
> Components: Broker
> Affects Versions: 2.28.0
> Reporter: Robbie Gemmell
> Priority: Major
>
> (Title is a little bit of a guess based on what a test is doing, the
> exceptions logged as a result, and the fact it poisoned a subsequent test).
> Closing a session with recent 'async acks' from using option
> 'blockOnAcknowledge=false' appears to lead to possible exceptions on the
> broker (snippet later), seemingly from a race between consumer cleanup during
> this, and processing of the previous acknowledgements.
> AcknowledgementTest.testNonBlockingAckPerf sends messages and then consumes
> them two seperate queues with 'blockOnAcknowledge=false' and
> 'blockOnAcknowledge=true' and compares duration. When it is done consuming,
> it closes the session (but not consumer) and connection. Invariably, it logs
> stacktraces like below during execution of this test (not obvious from
> default output, but is when turning on some debug instrumentation of which
> test is starting/stopping). After this happens, the test that follows would
> fail due to finding an extra message on a queue (queue1) they both used (this
> was reported in ARTEMIS-4082 against testDupsOKAcknowledgeQueue).
> Changing AcknowledgementTest.testNonBlockingAckPerf to closely inspect the
> counts after it is main work is finished, it then fails sporadically as or
> more often than it was causing testDupsOKAcknowledgeQueue to fail. Siilarly,
> isolating testNonBlockingAckPerf to its own queues looks to stop
> testDupsOKAcknowledgeQueue sporadically failing, which is what will be done
> here initially.
> Example output during failure in recent run:
> https://github.com/apache/activemq-artemis/actions/runs/4691971133/jobs/8317110969#step:5:33384
> {noformat}
> [Thread-0
> (ActiveMQ-remoting-threads-ActiveMQServerImpl::name=localhost-195163481)]
> 17:20:43,422 WARN [org.apache.activemq.artemis.core.server] AMQ222061:
> Client connection failed, clearing up resources for session
> 855206e2-da1f-11ed-8303-000d3aa462b0
> [Thread-0
> (ActiveMQ-remoting-threads-ActiveMQServerImpl::name=localhost-195163481)]
> 17:20:43,430 WARN [org.apache.activemq.artemis.core.server] AMQ222107:
> Cleared up resources for session 855206e2-da1f-11ed-8303-000d3aa462b0
> [Thread-7
> (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@fd46303)]
> 17:20:43,446 ERROR [org.apache.activemq.artemis.core.server] AMQ224016:
> Caught exception
> org.apache.activemq.artemis.api.core.ActiveMQIllegalStateException:
> AMQ229028: Consumer 0 doesn't exist on the server
> at
> org.apache.activemq.artemis.core.server.impl.ServerSessionImpl.findConsumer(ServerSessionImpl.java:1267)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at
> org.apache.activemq.artemis.core.server.impl.ServerSessionImpl.acknowledge(ServerSessionImpl.java:1234)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at
> org.apache.activemq.artemis.core.protocol.core.ServerSessionPacketHandler.onSessionAcknowledge(ServerSessionPacketHandler.java:762)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at
> org.apache.activemq.artemis.core.protocol.core.ServerSessionPacketHandler.onMessagePacket(ServerSessionPacketHandler.java:302)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at org.apache.activemq.artemis.utils.actors.Actor.doTask(Actor.java:32)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.ProcessorBase.executePendingTasks(ProcessorBase.java:68)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:57)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:32)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.ProcessorBase.executePendingTasks(ProcessorBase.java:68)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
> ~[?:?]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
> ~[?:?]
> at
> org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> [Thread-7
> (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@fd46303)]
> 17:20:43,463 ERROR [org.apache.activemq.artemis.core.server] AMQ224016:
> Caught exception
> org.apache.activemq.artemis.api.core.ActiveMQIllegalStateException:
> AMQ229028: Consumer 0 doesn't exist on the server
> at
> org.apache.activemq.artemis.core.server.impl.ServerSessionImpl.findConsumer(ServerSessionImpl.java:1267)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at
> org.apache.activemq.artemis.core.server.impl.ServerSessionImpl.acknowledge(ServerSessionImpl.java:1234)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at
> org.apache.activemq.artemis.core.protocol.core.ServerSessionPacketHandler.onSessionAcknowledge(ServerSessionPacketHandler.java:762)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at
> org.apache.activemq.artemis.core.protocol.core.ServerSessionPacketHandler.onMessagePacket(ServerSessionPacketHandler.java:302)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at org.apache.activemq.artemis.utils.actors.Actor.doTask(Actor.java:32)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.ProcessorBase.executePendingTasks(ProcessorBase.java:68)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:57)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:32)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.ProcessorBase.executePendingTasks(ProcessorBase.java:68)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
> ~[?:?]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
> ~[?:?]
> at
> org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> [Thread-7
> (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@fd46303)]
> 17:20:43,470 ERROR [org.apache.activemq.artemis.core.server] AMQ224016:
> Caught exception
> org.apache.activemq.artemis.api.core.ActiveMQIllegalStateException:
> AMQ229028: Consumer 0 doesn't exist on the server
> at
> org.apache.activemq.artemis.core.server.impl.ServerSessionImpl.findConsumer(ServerSessionImpl.java:1267)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at
> org.apache.activemq.artemis.core.server.impl.ServerSessionImpl.acknowledge(ServerSessionImpl.java:1234)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at
> org.apache.activemq.artemis.core.protocol.core.ServerSessionPacketHandler.onSessionAcknowledge(ServerSessionPacketHandler.java:762)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at
> org.apache.activemq.artemis.core.protocol.core.ServerSessionPacketHandler.onMessagePacket(ServerSessionPacketHandler.java:302)
> ~[artemis-server-2.29.0-SNAPSHOT.jar:2.29.0-SNAPSHOT]
> at org.apache.activemq.artemis.utils.actors.Actor.doTask(Actor.java:32)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.ProcessorBase.executePendingTasks(ProcessorBase.java:68)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:57)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:32)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> org.apache.activemq.artemis.utils.actors.ProcessorBase.executePendingTasks(ProcessorBase.java:68)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
> ~[?:?]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
> ~[?:?]
> at
> org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)
> ~[artemis-commons-2.29.0-SNAPSHOT.jar:?]
> ..etc etc etc..
> {noformat}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
