You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@activemq.apache.org by "Matt Pavlovich (Jira)" <ji...@apache.org> on 2023/04/04 14:55:00 UTC
[jira] [Updated] (AMQ-9070) Async error occurred
[ https://issues.apache.org/jira/browse/AMQ-9070?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matt Pavlovich updated AMQ-9070:
--------------------------------
Fix Version/s: 5.18.2
(was: 5.18.1)
> Async error occurred
> --------------------
>
> Key: AMQ-9070
> URL: https://issues.apache.org/jira/browse/AMQ-9070
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.16.3
> Environment: Enviroment: Red Hat Linux 8.2
> Version of ActiveMQ: 5.16.3
> Java Version: openJDK version "11.0.7" 2020-04-14 LTS
> Reporter: Jerrold Stoy
> Assignee: Jean-Baptiste Onofré
> Priority: Major
> Fix For: 5.17.5, 5.18.2
>
>
> I have a broker on a host that I call the app-server. The broker client is on a host called app-client.
>
> The server and client communcate between two queues. The client sends request to the REQUEST queue and the server responds back to the client on a RESPONSE queue.
> On the queue Producer the deliveryMode is set to NON_PERSISTENT, and the timeToLive is set for about a minutes.
>
> The client connects to the broker using the url: "failover:(tcp://44.42.3.220:40220)?maxCacheSixe=xxx&trackMessages=true" this is deal with machines coming up in any order. I also have disabled the Jetty Admin console as per RedHat Bug [1061847|tel:1061847] [https://bugzilla.redhat.com/show_bug.cgi?id=1061847]
>
> We have a system test that during the test it shuts down the network interface and later restarts the network interface. The test is trying to mimic a brief network outage. Occassionally when the test is run I see the following in broker log file:
>
> 2022-08-31 20:08:27,299 | INFO | Apache ActiveMQ 5.16.3 (localhost, ID:app-server-33483-1661976507140-0:1) is starting | org.apache.activemq.broker.BrokerService | main
> 2022-08-31 20:08:27,659 | INFO | Listening for connections at: tcp://44.42.3.1:40220?maximumConnections=1000&wireFormat.maxFrameSize=104857600 | org.apache.activemq.transport.TransportServerThreadSupport | main
> 2022-08-31 20:08:27,674 | INFO | Connector tcp40220 started | org.apache.activemq.broker.TransportConnector | main
> 2022-08-31 20:08:27,675 | INFO | Apache ActiveMQ 5.16.3 (localhost, ID:app-server-33483-1661976507140-0:1) started | org.apache.activemq.broker.BrokerService | main
> 2022-08-31 20:08:27,676 | INFO | For help or more information please see: [http://activemq.apache.org|http://activemq.apache.org/] | org.apache.activemq.broker.BrokerService | main
> 2022-08-31 20:12:51,237 | WARN | Async error occurred | org.apache.activemq.broker.TransportConnection.Service | ActiveMQ Transport: tcp:///44.42.3.220:44224@40220
> javax.jms.JMSException: Could not correlate acknowledgment with dispatched message: MessageAck \{commandId = 23, responseRequired = false, ackType = 1, consumerId = ID:app-client-38581-1661976570805-1:1:1:1, firstMessageId = ID:app-server-41559-1661976536817-1:1:1:1:17, lastMessageId = ID:app-server-41559-1661976536817-1:1:1:1:17, destination = queue://RESPONSE, transactionId = null, messageCount = 1, poisonCause = java.lang.Throwable: Suppressing duplicate delivery on connection, consumer ID:app-client-38581-1661976570805-1:1:1:1}
> at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:381)
> at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:534)
> at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:493)
> at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:89)
> at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:89)
> at org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:278)
> at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:89)
> at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:590)
> at org.apache.activemq.command.MessageAck.visit(MessageAck.java:245)
> at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:336)
> at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:200)
> at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:125)
> at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:301)
> at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
> at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:233)
> at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:215)
> at java.base/java.lang.Thread.run(Thread.java:834)
> 2022-08-31 20:14:52,946 | INFO | Apache ActiveMQ 5.16.3 (localhost, ID:app-server-33483-1661976507140-0:1) is shutting down | org.apache.activemq.broker.BrokerService | ActiveMQ ShutdownHook
> 2022-08-31 20:14:53,080 | INFO | Connector tcp40220 stopped | org.apache.activemq.broker.TransportConnector | ActiveMQ ShutdownHook
> 2022-08-31 20:14:53,113 | INFO | PListStore:[/opt/app/brokers/broker_220/data/localhost/tmp_storage] stopped | org.apache.activemq.store.kahadb.plist.PListStoreImpl | ActiveMQ ShutdownHook
> 2022-08-31 20:14:53,114 | INFO | Stopping async queue tasks | org.apache.activemq.store.kahadb.KahaDBStore | ActiveMQ ShutdownHook
> 2022-08-31 20:14:53,114 | INFO | Stopping async topic tasks | org.apache.activemq.store.kahadb.KahaDBStore | ActiveMQ ShutdownHook
> 2022-08-31 20:14:53,116 | INFO | Stopped KahaDB | org.apache.activemq.store.kahadb.KahaDBStore | ActiveMQ ShutdownHook
> 2022-08-31 20:14:53,132 | INFO | Apache ActiveMQ 5.16.3 (localhost, ID:app-server-33483-1661976507140-0:1) uptime 6 minutes | org.apache.activemq.broker.BrokerService | ActiveMQ ShutdownHook
> 2022-08-31 20:14:53,133 | INFO | Apache ActiveMQ 5.16.3 (localhost, ID:app-server-33483-1661976507140-0:1) is shutdown | org.apache.activemq.broker.BrokerService | ActiveMQ ShutdownHook
> 2022-08-31 20:14:53,135 | INFO | Closing [org.apache.activemq.xbean.XBeanBrokerFactory$1@74a10858|mailto:org.apache.activemq.xbean.XBeanBrokerFactory$1@74a10858]: startup date [Wed Aug 31 20:08:21 UTC 2022]; root of context hierarchy | org.apache.activemq.xbean.XBeanBrokerFactory$1 | ActiveMQ ShutdownHook
> 2022-08-31 20:16:17,471 | INFO | Refreshing [org.apache.activemq.xbean.XBeanBrokerFactory$1@74a10858|mailto:org.apache.activemq.xbean.XBeanBrokerFactory$1@74a10858]: startup date [Wed Aug 31 20:16:17 UTC 2022]; root of context hierarchy | org.apache.activemq.xbean.XBeanBrokerFactory$1 | main
> 2022-08-31 20:16:21,367 | INFO | Using Persistence Adapter: KahaDBPersistenceAdapter[/opt/app/brokers/broker_220/data/kahadb] | org.apache.activemq.broker.BrokerService | main
> 2022-08-31 20:16:21,725 | INFO | KahaDB is version 7 | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2022-08-31 20:16:21,792 | INFO | PListStore:[/opt/app/brokers/broker_220/data/localhost/tmp_storage] started | org.apache.activemq.store.kahadb.plist.PListStoreImpl | main
> 2022-08-31 20:16:22,119 | INFO | Apache ActiveMQ 5.16.3 (localhost, ID:app-server-38759-1661976981932-0:1) is starting | org.apache.activemq.broker.BrokerService | main
> 2022-08-31 20:16:22,315 | INFO | Listening for connections at: tcp://44.42.3.1:40220?maximumConnections=1000&wireFormat.maxFrameSize=104857600 | org.apache.activemq.transport.TransportServerThreadSupport | main
> 2022-08-31 20:16:22,338 | INFO | Connector tcp40220 started | org.apache.activemq.broker.TransportConnector | main
>
>
> On the client side I am seeing the following message logged:
> 2022-08-31T20:12:51.262000+00:00 WARNING JMSHelper onException The broker connection is broken, and has thrown the following exception: javax.jms.JMSException: Could not correlate acknowledgment with dispatched message: MessageAck \{commandId = 23, responseRequired = false, ackType = 1, consumerId = ID:app-client-38581-1661976570805-1:1:1:1, firstMessageId = ID:app-server-41559-1661976536817-1:1:1:1:17, lastMessageId = ID:app-server-41559-1661976536817-1:1:1:1:17, destination = queue://RESPONSE, transactionId = null, messageCount = 1, poisonCause = java.lang.Throwable: Suppressing duplicate delivery on connection, consumer ID:app-client-38581-1661976570805-1:1:1:1}
>
> Would anything in my configuration be causing the error that occurs at 2022-08-31 20:12:51,237 | WARN | Async error occurred | org.apache.activemq.broker.TransportConnection.Service | ActiveMQ Transport: tcp:///44.42.3.220:44224@40220. Is there anything that I can do to prevent the error from occurring?
>
> I have found similar posts on the web - but have not seen any explanation or solutions.
>
> Any help would be greatly appreciated.
>
> # Stoy
--
This message was sent by Atlassian Jira
(v8.20.10#820010)