Robbie Gemmell created ARTEMIS-4242:
---------------------------------------
Summary: 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
(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. 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 mroe
often than it was causing testDupsOKAcknowledgeQueue to fail.
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)
