I am using 5.7.0 with Java 1.7.0_07 on a linux 64 system. Messages are
persisted using KahaDB as the store.
* I have a test which puts 10 messages on a queue. This queue is being read
via a transacted consumer.
* I then shutdown the broker without committing or rolling back the session.
I am doing this with an embedded broker, so the process does /not/ get shut
down.
* I then restart the broker and read the queue, again with a transacted
consumer.
* Sometimes (about 5% maybe) after the restart only 9 messages are on the
queue.
* There are no ActiveMQ or KahaDB ERRORs when this occurs
* It seems that it is always the first message that was put on the queue
which is missing
I've replicated this with full trace logging for com.apache.activemq. It's
a lot of logs, so I've just included the ones which mention the specific
queue. I'd appreciate any guidance on tracking down what the problem is.
Logs
/I use a QueueBrowser to check the queue right before shutdown/
2012-10-25 22:12:15,736 INFO JmsTestUtils - queue
'indexer.index-content-dispatcher' has msgIds: 1, 2, 3, 4, 6, 5, 7, 9, 8, 10
2012-10-25 22:12:15,737 TRACE PrefetchSubscription - ack:MessageAck
{commandId = 13, responseRequired = false, ackType = 2, consumerId =
ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:9:1:1, firstMessageId =
ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:3:1:1:9, lastMessageId
= ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:3:1:1:9, destination
= queue://indexer.index-content-dispatcher, transactionId = null,
messageCount = 1, poisonCause = null}
2012-10-25 22:12:15,738 TRACE PrefetchSubscription - ack:MessageAck
{commandId = 14, responseRequired = false, ackType = 2, consumerId =
ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:9:1:1, firstMessageId =
ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:3:1:1:10, lastMessageId
= ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:3:1:1:10, destination
= queue://indexer.index-content-dispatcher, transactionId = null,
messageCount = 1, poisonCause = null}
2012-10-25 22:12:15,738 DEBUG ManagementContext - Unregistering MBean
ActiveMQ.Attivio:BrokerName=local-jmsBroker,Type=Subscription,persistentMode=Non-Durable,destinationType=Queue,destinationName=indexer.index-content-dispatcher,clientId=ID_vmnode-073.corp.attivio.com-42823-1351217522424-4_9,consumerId=ID_vmnode-073.corp.attivio.com-42823-1351217522424-5_9_1_1
2012-10-25 22:12:15,738 DEBUG AbstractRegion - local-jmsBroker removing
consumer: ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:9:1:1 for
destination: queue://indexer.index-content-dispatcher
2012-10-25 22:12:15,738 DEBUG Queue -
queue://indexer.index-content-dispatcher remove sub:
QueueBrowserSubscription:
consumer=ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:9:1:1,
destinations=1, dispatched=0, delivered=0, pending=0, lastDeliveredSeqId:
80, dequeues: 0, dispatched: 20, inflight: 10
2012-10-25 22:12:15,738 TRACE PooledTaskRunner - Running task iteration 0 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,738 TRACE PooledTaskRunner - Running task iteration 1 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,738 TRACE PooledTaskRunner - Running task iteration 2 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,738 TRACE PooledTaskRunner - Run task done:
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,770 TRACE PrefetchSubscription - ack:MessageAck
{commandId = 15, responseRequired = false, ackType = 2, consumerId =
ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:4:1:1, firstMessageId =
ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:3:1:1:1, lastMessageId
= ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:3:1:1:10, destination
= queue://indexer.index-content-dispatcher, transactionId =
TX:ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:4:2, messageCount =
10, poisonCause = null}
2012-10-25 22:12:15,771 TRACE PooledTaskRunner - Running task iteration 0 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,772 TRACE PooledTaskRunner - Running task iteration 1 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,772 TRACE PooledTaskRunner - Running task iteration 2 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,772 TRACE PooledTaskRunner - Running task iteration 3 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,772 TRACE PooledTaskRunner - Running task iteration 4 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,772 TRACE PooledTaskRunner - Running task iteration 5 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,772 TRACE PooledTaskRunner - Running task iteration 6 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,773 TRACE PooledTaskRunner - Running task iteration 7 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,773 TRACE PooledTaskRunner - Running task iteration 8 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,773 TRACE PooledTaskRunner - Running task iteration 9 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,773 TRACE PooledTaskRunner - Running task iteration 10 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,773 TRACE PooledTaskRunner - Run task done:
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,774 TRACE PooledTaskRunner - Running task iteration 0 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,774 TRACE PooledTaskRunner - Run task done:
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,780 DEBUG ManagementContext - Unregistering MBean
ActiveMQ.Attivio:BrokerName=local-jmsBroker,Type=Subscription,persistentMode=Non-Durable,destinationType=Queue,destinationName=indexer.index-content-dispatcher,clientId=ID_vmnode-073.corp.attivio.com-42823-1351217522424-4_4,consumerId=ID_vmnode-073.corp.attivio.com-42823-1351217522424-5_4_1_1
2012-10-25 22:12:15,797 DEBUG AbstractRegion - local-jmsBroker removing
consumer: ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:4:1:1 for
destination: queue://indexer.index-content-dispatcher
2012-10-25 22:12:15,797 DEBUG Queue -
queue://indexer.index-content-dispatcher remove sub: QueueSubscription:
consumer=ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:4:1:1,
destinations=1, dispatched=10, delivered=10, pending=0, lastDeliveredSeqId:
80, dequeues: 0, dispatched: 20, inflight: 10
2012-10-25 22:12:15,797 TRACE PooledTaskRunner - Running task iteration 0 -
queue://indexer.index-content-dispatcher, subscriptions=0, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,798 DEBUG Queue - indexer.index-content-dispatcher
toPageIn: 0, Inflight: 0, pagedInMessages.size 10, enqueueCount: 10,
dequeueCount: 0
2012-10-25 22:12:15,798 TRACE PooledTaskRunner - Run task done:
queue://indexer.index-content-dispatcher, subscriptions=0, memory=0%,
size=0, in flight groups=active message group buckets: 0
2012-10-25 22:12:15,823 DEBUG ManagementContext - Unregistering MBean
ActiveMQ.Attivio:BrokerName=local-jmsBroker,Type=Producer,destinationType=Queue,destinationName=indexer.index-content-dispatcher,clientId=ID_vmnode-073.corp.attivio.com-42823-1351217522424-4_3,producerId=ID_vmnode-073.corp.attivio.com-42823-1351217522424-5_3_1_1
2012-10-25 22:12:19,698 TRACE PooledTaskRunner - Shutdown timeout:
queue://indexer.index-content-dispatcher, subscriptions=0, memory=0%,
size=0, in flight groups=active message group buckets: 0 task: {}
2012-10-25 22:12:19,698 TRACE PooledTaskRunner - Shutdown timeout: Topic:
destination=ActiveMQ.Advisory.Producer.Queue.indexer.index-content-dispatcher,
subscriptions=0 task: {}
2012-10-25 22:12:19,698 TRACE PooledTaskRunner - Shutdown timeout: Topic:
destination=ActiveMQ.Advisory.Consumer.Queue.indexer.index-content-dispatcher,
subscriptions=0 task: {}
2012-10-25 22:12:19,700 DEBUG ManagementContext - Unregistering MBean
ActiveMQ.Attivio:BrokerName=local-jmsBroker,Type=Queue,Destination=indexer.index-content-dispatcher
2012-10-25 22:12:19,700 DEBUG ManagementContext - Unregistering MBean
ActiveMQ.Attivio:BrokerName=local-jmsBroker,Type=Topic,Destination=ActiveMQ.Advisory.Consumer.Queue.indexer.index-content-dispatcher
2012-10-25 22:12:19,700 DEBUG ManagementContext - Unregistering MBean
ActiveMQ.Attivio:BrokerName=local-jmsBroker,Type=Topic,Destination=ActiveMQ.Advisory.Producer.Queue.indexer.index-content-dispatcher
Broker shutdown, note on restart only 9 messages are present!
2012-10-25 22:12:21,743 INFO QueueCreationTrackingPlugin - Adding
destination indexer.index-content-dispatcher
2012-10-25 22:12:21,743 DEBUG AbstractRegion - local-jmsBroker adding
destination: queue://indexer.index-content-dispatcher
2012-10-25 22:12:21,746 DEBUG Queue - indexer.index-content-dispatcher
toPageIn: 9, Inflight: 0, pagedInMessages.size 0, enqueueCount: 0,
dequeueCount: 0
2012-10-25 22:12:21,746 DEBUG Queue - indexer.index-content-dispatcher
toPageIn: 9, Inflight: 0, pagedInMessages.size 0, enqueueCount: 0,
dequeueCount: 0
2012-10-25 22:12:21,747 INFO QueueCreationTrackingPlugin - Adding
destination indexer.index-content-dispatcher
2012-10-25 22:12:21,748 INFO QueueCreationTrackingPlugin - Adding
destination indexer.index-content-dispatcher
2012-10-25 22:12:22,076 DEBUG AbstractRegion - local-jmsBroker adding
consumer: ID:vmnode-073.corp.attivio.com-42823-1351217522424-7:2:1:1 for
destination: queue://indexer.index-content-dispatcher
2012-10-25 22:12:22,078 DEBUG Queue -
queue://indexer.index-content-dispatcher add sub: QueueSubscription:
consumer=ID:vmnode-073.corp.attivio.com-42823-1351217522424-7:2:1:1,
destinations=0, dispatched=0, delivered=0, pending=0, dequeues: 0,
dispatched: 0, inflight: 0
2012-10-25 22:12:22,078 DEBUG AbstractRegion - local-jmsBroker adding
destination:
topic://ActiveMQ.Advisory.Consumer.Queue.indexer.index-content-dispatcher
2012-10-25 22:12:22,079 TRACE PooledTaskRunner - Running task iteration 0 -
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=9, in flight groups=null
2012-10-25 22:12:22,079 DEBUG Queue - indexer.index-content-dispatcher
toPageIn: 9, Inflight: 0, pagedInMessages.size 0, enqueueCount: 0,
dequeueCount: 0
2012-10-25 22:12:22,083 TRACE AbstractStoreCursor -
org.apache.activemq.broker.region.cursors.QueueStorePrefetch@17d58cae:indexer.index-content-dispatcher,batchResetNeeded=false,storeHasMessages=true,size=9,cacheEnabled=false,maxBatchSize:9
- fillBatch
2012-10-25 22:12:22,090 TRACE AbstractStoreCursor -
org.apache.activemq.broker.region.cursors.QueueStorePrefetch@17d58cae:indexer.index-content-dispatcher,batchResetNeeded=false,storeHasMessages=true,size=0,cacheEnabled=false,maxBatchSize:9
- fillBatch
2012-10-25 22:12:22,091 TRACE PooledTaskRunner - Run task done:
queue://indexer.index-content-dispatcher, subscriptions=1, memory=0%,
size=0, in flight groups=null
2012-10-25 22:12:22,096 TRACE PrefetchSubscription -
ID:vmnode-073.corp.attivio.com-42823-1351217522424-7:2:1:1 dispatched:
ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:3:1:1:2 -
queue://indexer.index-content-dispatcher, dispatched: 3, inflight: 3
2012-10-25 22:12:22,096 TRACE PrefetchSubscription -
ID:vmnode-073.corp.attivio.com-42823-1351217522424-7:2:1:1 dispatched:
ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:3:1:1:3 -
queue://indexer.index-content-dispatcher, dispatched: 3, inflight: 3
2012-10-25 22:12:22,096 TRACE PrefetchSubscription -
ID:vmnode-073.corp.attivio.com-42823-1351217522424-7:2:1:1 dispatched:
ID:vmnode-073.corp.attivio.com-42823-1351217522424-5:3:1:1:4 -
queue://indexer.index-content-dispatcher, dispatched: 3, inflight: 3
--
View this message in context:
http://activemq.2283324.n4.nabble.com/Message-sometimes-lost-when-transaction-open-and-broker-restarted-tp4658295.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.
