Uploaded image for project: 'AMQ Broker'
  1. AMQ Broker
  2. ENTMQBR-155

InactivityIOException - Perhaps No Keep Alives From Broker?

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major Major
    • A-MQ 7.0.0.ER11
    • A-MQ 7.0.0.GA
    • None
    • None

      I've been trying out the "A-MQ7-7.0.0.ER9-redhat-1" broker and noted the following.

      • I point my "5.11.0.redhat-621084" OpenWire producer and consumer to the AMQ7 broker
      • They use failover://tcp://localhost:61616 to connect to the local broker
      • Producer sends 20 messages to broker, consumers begins to consume.
      • I have the consumer configured to use client ack and also wait 5 seconds in-between reading a message and acknowledging it.
      • At around the 12th message, the consumer gets the following exception and a duplicate message.
      1:Received: Message: 12 sent at: Wed Aug 24 14:43:58 EDT 2016X...
 WARN | Transport (tcp://localhost:61616) failed, attempting to automatically reconnect
org.apache.activemq.transport.InactivityIOException: Channel was inactive for too (>30000) long: tcp://127.0.0.1:61616
        at org.apache.activemq.transport.AbstractInactivityMonitor$5.run(AbstractInactivityMonitor.java:245)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
 INFO | Successfully reconnected to tcp://localhost:61616
1:Received: Message: 12 sent at: Wed Aug 24 14:43:58 EDT 2016X...

      Happens every time.

      On the broker end, I am seeing the following in the logs:

      14:45:01,447 WARN  [org.apache.activemq.artemis.core.server] AMQ222067: Connection failure has been detected: null [code=REMOTE_DISCONNECT]
14:45:01,447 WARN  [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session b38705d5-6a2a-11e6-9590-70cd60ff4688
14:45:01,448 WARN  [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session b38705d5-6a2a-11e6-9590-70cd60ff4688
14:45:01,448 WARN  [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session ID:Joe-Fernandezs-iMac.local-59091-1472064231233-1:1:-1
14:45:01,449 WARN  [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session ID:Joe-Fernandezs-iMac.local-59091-1472064231233-1:1:-1
14:45:01,459 WARN  [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session ID:Joe-Fernandezs-iMac.local-59091-1472064231233-1:1:1
14:45:01,460 WARN  [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session ID:Joe-Fernandezs-iMac.local-59091-1472064231233-1:1:1
14:45:01,475 INFO  [org.apache.activemq.artemis.core.server] AMQ221052: trying to deploy topic jms.topic.ActiveMQ.Advisory.TempQueue
14:45:01,499 INFO  [org.apache.activemq.artemis.core.server] AMQ221052: trying to deploy topic jms.topic.ActiveMQ.Advisory.TempTopic

      If I use auto ack, instead of client ack, I don't get a dup, but still get this on the client side:

      1:Received: Message: 12 sent at: Wed Aug 24 15:07:48 EDT 2016X...
 WARN | Transport (tcp://localhost:61616) failed, attempting to automatically reconnect
org.apache.activemq.transport.InactivityIOException: Channel was inactive for too (>30000) long: tcp://127.0.0.1:61616
        at org.apache.activemq.transport.AbstractInactivityMonitor$5.run(AbstractInactivityMonitor.java:245)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
 INFO | Successfully reconnected to tcp://localhost:61616
 WARN | ID:Joe-Fernandezs-iMac.local-59114-1472065662090-1:1:1:1 suppressing duplicate delivery on connection, poison acking: MessageDispatch {commandId = 0, responseRequired = false, consumerId = ID:Joe-Fernandezs-iMac.local-59114-1472065662090-1:1:1:1, destination = queue://TOOL.DEFAULT, message = ActiveMQTextMessage {commandId = 17, responseRequired = false, messageId = ID:Joe-Fernandezs-iMac.local-59116-1472065668183-1:1:1:1:13, originalDestination = null, originalTransactionId = null, producerId = ID:Joe-Fernandezs-iMac.local-59116-1472065668183-1:1:1:1, destination = queue://TOOL.DEFAULT, transactionId = null, expiration = 0, timestamp = 1472065668465, arrival = 0, brokerInTime = 1472065668465, brokerOutTime = 1472065733463, correlationId = null, replyTo = null, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = org.apache.activemq.util.ByteSequence@76d7510f, marshalledP!
 roperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = true, readOnlyBody = true, droppable = false, jmsXGroupFirstForConsumer = false, text = Message: 12 sent at: Wed Aug 24 15:07:48 EDT ...XXXXXXXXXXXE}, redeliveryCounter = 0}

      The broker puts out the following:

      15:08:53,490 WARN  [org.apache.activemq.artemis.core.server] AMQ222149: Message Reference[1224]:RELIABLE:ServerMessage[messageID=1224,durable=true,userID=null,priority=4, bodySize=1284, timestamp=Wed Aug 24 15:07:48 EDT 2016,expiration=0, durable=true, address=jms.queue.TOOL.DEFAULT,properties=TypedProperties[__HDR_dlqDeliveryFailureCause=java.lang.Throwable: Suppressing duplicate delivery on connection, consumer ID:Joe-Fernandezs-iMac.local-59114-1472065662090-1:1:1:1,__HDR_BROKER_IN_TIME=1472065668465,__HDR_ARRIVAL=0,__HDR_GROUP_SEQUENCE=0,__HDR_COMMAND_ID=17,__HDR_PRODUCER_ID=[0000 003D 7B01 2B00 3449 443A 4A6F 652D 4665 726E 616E 6465 7A73 2D69 4D61  ... 61 6C2D 3539 3131 362D 3134 3732 3036 3536 3638 3138 332D 313A 3100 0100 01),_AMQ_DUPL_ID=ID:Joe-Fernandezs-iMac.local-59116-1472065668183-1:1:1:1:13,__HDR_MESSAGE_ID=[0000 0041 6E02 AE02 7B00 3449 443A 4A6F 652D 4665 726E 616E 6465 7A73 2D69  ... 2D 3539 3131 362D 3134 3732 3036 3536 3638 3138 332D 313A 3100 0100 0100 0!
 D),__HDR_DROPPABLE=false]]@1075545055 has reached maximum delivery attempts, sending it to Dead Letter Address jms.queue.DLQ from jms.queue.TOOL.DEFAULT

      If I reduce the turnaround time for the consumer to something less than 5 seconds, it works fine. Also, problem doesn't occur when clients connect to a 6.2.1 A-MQ broker.

            gaohoward Howard Gao
            Argo_Integration Travis North (Inactive)
            Travis North Travis North (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: