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
