Take a look at the following test case (attached). I cannot seem to reproduce on 5.7.0 or on trunk. Can you modify the testcase to fit your use case?
On Fri, Oct 26, 2012 at 5:47 AM, mserrano <mar...@attivio.com> wrote: > 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. > -- *Christian Posta* http://www.christianposta.com/blog twitter: @christianposta