Uploaded image for project: 'ActiveMQ Artemis'
  1. ActiveMQ Artemis
  2. ARTEMIS-4242

closing session with recent 'async acks' can lead to exceptions from apparent consumer cleanup race

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Reopened
    • Major
    • Resolution: Unresolved
    • 2.28.0, 2.29.0
    • None
    • Broker
    • None

    Description

      (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

      [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..
      

      Attachments

        Issue Links

          Activity

            People

              Unassigned Unassigned
              robbie Robbie Gemmell
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated: