Uploaded image for project: 'JBoss A-MQ'
  1. JBoss A-MQ
  2. ENTMQ-2009

Contention with RAR localTransaction rollback, non transacted ack in the mix in error

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Won't Do
    • Icon: Major Major
    • None
    • JBoss A-MQ 6.3
    • camel, jms-client, JTA, RAR
    • None

      It appears that a an transacted ack rollback is not isolated, the session can still ack concurrently if nudged in that direction. The net result is two acks, one with no transaction that succeeds.
      The use case is SY, jms-binding - camel-jms spring-dmlc and JTA.
      Trace logging:

      18:23:09,802 DEBUG [org.apache.activemq.transport.TransportLogger.Connection:4] (ActiveMQ Transport: tcp:///x.y.z:61616@40229) RECEIVED: MessageDispatch {commandId = 0, responseRequired = false, consumerId = ID:dhcp181-106.boo.com-52135-1479338165120-13:1:38:1, destination = queue://queue/in, message = ActiveMQTextMessage {commandId = 296, responseRequired = false, messageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, originalDestination = null, originalTransactionId = null, producerId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1, destination = queue://queue/in, transactionId = null, expiration = 0, timestamp = 1479338407485, arrival = 0, brokerInTime = 1479338415594, brokerOutTime = 1479338597910, 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@65bb1a9, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, jmsXGroupFirstForConsumer = false, text = <?xml version="1.0" encoding="UTF-8" ?>
      18:23:09,805 TRACE [org.apache.activemq.ActiveMQMessageConsumer] (Camel (camel-4) thread #7 - JmsConsumer[queue/in]) ID:dhcp181-106.boo.com-52135-1479338165120-13:1:38:1 received message: MessageDispatch {commandId = 0, responseRequired = false, consumerId = ID:dhcp181-106.boo.com-52135-1479338165120-13:1:38:1, destination = queue://queue/in, message = ActiveMQTextMessage {commandId = 296, responseRequired = false, messageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, originalDestination = null, originalTransactionId = null, producerId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1, destination = queue://queue/in, transactionId = null, expiration = 0, timestamp = 1479338407485, arrival = 0, brokerInTime = 1479338415594, brokerOutTime = 1479338597910, 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@65bb1a9, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = true, readOnlyBody = true, droppable = false, jmsXGroupFirstForConsumer = false, text = <?xml version="1.0" encoding="UTF-8" ?>
      18:23:13,927 DEBUG [org.apache.activemq.transport.TransportLogger.Connection:4] (Camel (camel-4) thread #7 - JmsConsumer[queue/in]) SENDING: MessageAck {commandId = 334, responseRequired = false, ackType = 2, consumerId = ID:dhcp181-106.boo.com-52135-1479338165120-13:1:38:1, firstMessageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, lastMessageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, destination = queue://queue/in, transactionId = TX:ID:dhcp181-106.boo.com-52135-1479338165120-13:1:38, messageCount = 1, poisonCause = null}
      18:23:13,952 DEBUG [org.apache.activemq.transport.TransportLogger.Connection:4] (Camel (camel-4) thread #7 - JmsConsumer[queue/in]) SENDING: MessageAck {commandId = 336, responseRequired = false, ackType = 1, consumerId = ID:dhcp181-106.boo.com-52135-1479338165120-13:1:38:1, firstMessageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, lastMessageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, destination = queue://queue/in, transactionId = null, messageCount = 1, poisonCause = java.lang.Throwable: Exceeded redelivery policy limit:RedeliveryPolicy {destination = null, collisionAvoidanceFactor = 0.15, maximumRedeliveries = 0, maximumRedeliveryDelay = -1, initialRedeliveryDelay = 1000, useCollisionAvoidance = false, useExponentialBackOff = false, backOffMultiplier = 5.0, redeliveryDelay = 1000}, cause:null}
      18:37:47,339 DEBUG [org.apache.activemq.transport.TransportLogger.Connection:110] (ActiveMQ Transport: tcp:///x.y.z:61616@40485) RECEIVED: MessageDispatch {commandId = 0, responseRequired = false, consumerId = ID:dhcp181-106.boo.com-52135-1479338165120-219:1:1:1, destination = queue://queue/in, message = ActiveMQTextMessage {commandId = 296, responseRequired = false, messageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, originalDestination = null, originalTransactionId = null, producerId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1, destination = queue://queue/in, transactionId = null, expiration = 0, timestamp = 1479338407485, arrival = 0, brokerInTime = 1479338603004, brokerOutTime = 1479339475362, 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@45429ffd, marshalledProperties = org.apache.activemq.util.ByteSequence@1915be91, dataStructure = null, redeliveryCounter = 1, size = 0, properties = {scheduledJobId=ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, redeliveryDelay=1000}, readOnlyProperties = false, readOnlyBody = false, droppable = false, jmsXGroupFirstForConsumer = false, text = <?xml version="1.0" encoding="UTF-8" ?>
      18:37:47,379 TRACE [org.apache.activemq.ActiveMQMessageConsumer] (Camel (camel-4) thread #3 - JmsConsumer[queue/in]) ID:dhcp181-106.boo.com-52135-1479338165120-219:1:1:1 received message: MessageDispatch {commandId = 0, responseRequired = false, consumerId = ID:dhcp181-106.boo.com-52135-1479338165120-219:1:1:1, destination = queue://queue/in, message = ActiveMQTextMessage {commandId = 296, responseRequired = false, messageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, originalDestination = null, originalTransactionId = null, producerId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1, destination = queue://queue/in, transactionId = null, expiration = 0, timestamp = 1479338407485, arrival = 0, brokerInTime = 1479338603004, brokerOutTime = 1479339475362, 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@45429ffd, marshalledProperties = org.apache.activemq.util.ByteSequence@1915be91, dataStructure = null, redeliveryCounter = 1, size = 0, properties = {scheduledJobId=ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, redeliveryDelay=1000}, readOnlyProperties = true, readOnlyBody = true, droppable = false, jmsXGroupFirstForConsumer = false, text = <?xml version="1.0" encoding="UTF-8" ?>
      18:38:32,455 DEBUG [org.apache.activemq.transport.TransportLogger.Connection:125] (ActiveMQ Transport: tcp:///x.y.z:61616@40508) RECEIVED: MessageDispatch {commandId = 0, responseRequired = false, consumerId = ID:dhcp181-106.boo.com-52135-1479338165120-249:1:1:1, destination = queue://queue/in, message = ActiveMQTextMessage {commandId = 296, responseRequired = false, messageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, originalDestination = null, originalTransactionId = null, producerId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1, destination = queue://queue/in, transactionId = null, expiration = 0, timestamp = 1479338407485, arrival = 0, brokerInTime = 1479338603004, brokerOutTime = 1479339520507, 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@5dcc0755, marshalledProperties = org.apache.activemq.util.ByteSequence@7df58d8e, dataStructure = null, redeliveryCounter = 2, size = 0, properties = {scheduledJobId=ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, redeliveryDelay=1000}, readOnlyProperties = false, readOnlyBody = false, droppable = false, jmsXGroupFirstForConsumer = false, text = <?xml version="1.0" encoding="UTF-8" ?>
      18:38:32,651 TRACE [org.apache.activemq.ActiveMQMessageConsumer] (Camel (camel-4) thread #8 - JmsConsumer[queue/in]) ID:dhcp181-106.boo.com-52135-1479338165120-249:1:1:1 received message: MessageDispatch {commandId = 0, responseRequired = false, consumerId = ID:dhcp181-106.boo.com-52135-1479338165120-249:1:1:1, destination = queue://queue/in, message = ActiveMQTextMessage {commandId = 296, responseRequired = false, messageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, originalDestination = null, originalTransactionId = null, producerId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1, destination = queue://queue/in, transactionId = null, expiration = 0, timestamp = 1479338407485, arrival = 0, brokerInTime = 1479338603004, brokerOutTime = 1479339520507, 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@5dcc0755, marshalledProperties = org.apache.activemq.util.ByteSequence@7df58d8e, dataStructure = null, redeliveryCounter = 2, size = 0, properties = {scheduledJobId=ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, redeliveryDelay=1000}, readOnlyProperties = true, readOnlyBody = true, droppable = false, jmsXGroupFirstForConsumer = false, text = <?xml version="1.0" encoding="UTF-8" ?>
      18:39:09,779 DEBUG [org.apache.activemq.transport.TransportLogger.Connection:125] (Camel (camel-4) thread #8 - JmsConsumer[queue/in]) SENDING: MessageAck {commandId = 7, responseRequired = false, ackType = 2, consumerId = ID:dhcp181-106.boo.com-52135-1479338165120-249:1:1:1, firstMessageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, lastMessageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, destination = queue://queue/in, transactionId = TX:ID:dhcp181-106.boo.com-52135-1479338165120-249:1:1, messageCount = 1, poisonCause = null}
      18:39:09,956 DEBUG [org.apache.activemq.transport.TransportLogger.Connection:125] (pool-24-thread-1) SENDING: MessageAck {commandId = 10, responseRequired = false, ackType = 2, consumerId = ID:dhcp181-106.boo.com-52135-1479338165120-249:1:1:1, firstMessageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, lastMessageId = ID:dhcp181-106.boo.com-53022-1479338331536-1:1:1:1:292, destination = queue://queue/in, transactionId = null, messageCount = 1, poisonCause = null}
      

            gtully@redhat.com Gary Tully
            gtully@redhat.com Gary Tully
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: