activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Martin Serrano (Created) (JIRA)" <j...@apache.org>
Subject [jira] [Created] (AMQ-3539) Prefetch state can be incorrect when transacted redelivery of duplicates occurs, causing stalled queue
Date Wed, 12 Oct 2011 18:03:11 GMT
Prefetch state can be incorrect when transacted redelivery of duplicates occurs, causing stalled
queue
------------------------------------------------------------------------------------------------------

                 Key: AMQ-3539
                 URL: https://issues.apache.org/jira/browse/AMQ-3539
             Project: ActiveMQ
          Issue Type: Bug
          Components: Broker, JMS client
    Affects Versions: 5.5.0
            Reporter: Martin Serrano
            Priority: Critical


* In ActiveMQMessageConsumer, delivery acks are generated by receive() calls and by the dispatch()
method when transacted redelivery of duplicates occurs.  These delivery acks are consolidated
by calling ackLater which batches them up using first/last message id and sends the acks as
appropriate w.r.t. the prefetch size.
* On the broker, the prefetch window is extended by checking the last message id, finding
where it is in the dispatched queue and incrementing the prefetchExtension accordingly.  This
algorithm depends on the consumer maintaining the dispatch order in its consolidated delivery
acks.
* When the transacted redelivery occurs, it happens in a separate thread than the receive,
operating on the latest delivered message.  The delivery acks from the receive thread are
arbitrarily delayed (but in order of dispatch) depending on client action.  The mixing of
these can result in an out of order consolidated delivery ack.

Real example (the client and broker logs are mixed to make it easier to follow; the dispatch
logs come from my own custom logging plugin):
{noformat}
2011-10-12 11:51:51,712 TRACE ActiveMqBroker [BrokerService[jmsBroker] Task-3] - Dispatching
message [ID:XXX-45585-1318434687322-0:68:1:1:1]
2011-10-12 11:51:51,834 TRACE ActiveMqBroker [BrokerService[jmsBroker] Task-43] - Dispatching
message [ID:XXX-60241-1318434687532-0:56:1:1:3]
2011-10-12 11:51:51,835 TRACE ActiveMqBroker [BrokerService[jmsBroker] Task-43] - Dispatching
message [ID:XXX-45585-1318434687322-0:68:1:1:2]

2011-10-12 11:51:51,836 DA [ActiveMQ Session Task-1] - ID:XXX-60241-1318434687532-0:33:1:1
tracking transacted redelivery of duplicate: ActiveMQTextMessage {commandId = 827, responseRequired
= true, messageId = ID:XXX-45585-1318434687322-0:68:1:1:2, originalDestination = null, originalTransactionId
= null, producerId = ID:XXX-45585-1318434687322-0:68:1:1, destination = queue://indexer.index-content-dispatcher,
transactionId = null, expiration = 0, timestamp = 1318434696398, arrival = 0, brokerInTime
= 1318434696461, brokerOutTime = 1318434711835, correlationId = null, replyTo = null, persistent
= true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null,
compressed = false, userID = null, content = null, marshalledProperties = org.apache.activemq.util.ByteSequence@305e3ad0,
dataStructure = null, redeliveryCounter = 0, size = 0, properties = XXX }

2011-10-12 11:51:51,876 TRACE ActiveMqBroker [ActiveMQ Transport: tcp:///127.0.0.1:55235]
- firstId: ID:XXX-45585-1318434687322-0:68:1:1:2, lastId: ID:XXX-45585-1318434687322-0:68:1:1:1,
dest: queue://indexer.index-content-dispatcher, acktype:0, individualAck:false, deliveredAck:true,
messageAck:true, standardAck:false

2011-10-12 11:51:51,878 TRACE ActiveMqBroker [BrokerService[jmsBroker] Task-8] - Dispatching
message [ID:XXX-60241-1318434687532-0:56:1:1:4]

2011-10-12 11:51:51,879 DA [ActiveMQ Session Task-1] - ID:XXX-60241-1318434687532-0:33:1:1
tracking transacted redelivery of duplicate: ActiveMQTextMessage {commandId = 840, responseRequired
= true, messageId = ID:XXX-60241-1318434687532-0:56:1:1:4, originalDestination = null, originalTransactionId
= null, producerId = ID:XXX-60241-1318434687532-0:56:1:1, destination = queue://indexer.index-content-dispatcher,
transactionId = null, expiration = 0, timestamp = 1318434696518, arrival = 0, brokerInTime
= 1318434696600, brokerOutTime = 1318434711878, correlationId = null, replyTo = null, persistent
= true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null,
compressed = false, userID = null, content = null, marshalledProperties = org.apache.activemq.util.ByteSequence@332a4674,
dataStructure = null, redeliveryCounter = 0, size = 0, properties = XXX }

2011-10-12 11:51:51,903 TRACE ActiveMqBroker [ActiveMQ Transport: tcp:///127.0.0.1:55235]
- firstId: ID:XXX-60241-1318434687532-0:56:1:1:4, lastId: ID:XXX-60241-1318434687532-0:56:1:1:3,
dest: queue://indexer.index-content-dispatcher, acktype:0, individualAck:false, deliveredAck:true,
messageAck:true, standardAck:false

2011-10-12 11:51:51,905 TRACE ActiveMqBroker [BrokerService[jmsBroker] Task-8] - Dispatching
message [ID:XXX-45585-1318434687322-0:68:1:1:3]

{noformat}



--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

Mime
View raw message