You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@activemq.apache.org by mserrano <ma...@attivio.com> on 2012/10/26 14:47:51 UTC
Message sometimes lost when transaction open and broker restarted
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.
Re: Message sometimes lost when transaction open and broker restarted
Posted by Christian Posta <ch...@gmail.com>.
Were you able to update the test I sent you to reproduce this?
On Thu, Nov 1, 2012 at 7:42 PM, mserrano <ma...@attivio.com> wrote:
> After deeper investigation, I have discovered that when this fails, it is
> because the first message (the one that ends up missing) is never written
> to
> the KahaDB store. I added a trace message to /void
> upadateIndex(Transaction
> tx, KahaAddMessageCommand command, Location location) / in order to see
> exactly when messages were persisted. When the test fails, the first
> message does not seem to enter this method. I continue to investigate.
>
>
>
> --
> View this message in context:
> http://activemq.2283324.n4.nabble.com/Message-sometimes-lost-when-transaction-open-and-broker-restarted-tp4658295p4658621.html
> Sent from the ActiveMQ - User mailing list archive at Nabble.com.
>
--
*Christian Posta*
http://www.christianposta.com/blog
twitter: @christianposta
Re: Message sometimes lost when transaction open and broker
restarted
Posted by mserrano <ma...@attivio.com>.
I've tracked down the issue but have not been able to reproduce it in a unit
test. I created a ticket for it:
https://issues.apache.org/jira/browse/AMQ-4157
--
View this message in context: http://activemq.2283324.n4.nabble.com/Message-sometimes-lost-when-transaction-open-and-broker-restarted-tp4658295p4658697.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.
Re: Message sometimes lost when transaction open and broker
restarted
Posted by mserrano <ma...@attivio.com>.
I tried for sometime to duplicate the issue with the test but was not able
to. So I am back to debugging this from my more complex environment.
--
View this message in context: http://activemq.2283324.n4.nabble.com/Message-sometimes-lost-when-transaction-open-and-broker-restarted-tp4658295p4658623.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.
Re: Message sometimes lost when transaction open and broker
restarted
Posted by mserrano <ma...@attivio.com>.
After deeper investigation, I have discovered that when this fails, it is
because the first message (the one that ends up missing) is never written to
the KahaDB store. I added a trace message to /void upadateIndex(Transaction
tx, KahaAddMessageCommand command, Location location) / in order to see
exactly when messages were persisted. When the test fails, the first
message does not seem to enter this method. I continue to investigate.
--
View this message in context: http://activemq.2283324.n4.nabble.com/Message-sometimes-lost-when-transaction-open-and-broker-restarted-tp4658295p4658621.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.
Re: Message sometimes lost when transaction open and broker restarted
Posted by Christian Posta <ch...@gmail.com>.
So using your orignal steps to recreate the issue, can you fill in where
you do the queue browsing?
* 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
On Tue, Oct 30, 2012 at 7:19 AM, mserrano <ma...@attivio.com> wrote:
> Thanks. I will try to. In part of my test I am using a QueueBrowser to
> inspect what is on the queue. I do this to check the state at various
> points to make sure it meets expectations. When I removed these checks
> (which weren't completely necessary), the problem when away. So my concern
> here is that since (I believe) the QueueBrowser is used for JMX inspection,
> does this leave a possible, albeit small, chance that using JMX will
> "corrupt" the state of a queue?
>
> I also confirmed that this is happening before the shutdown (i.e., not an
> issue with reading the KahaDB store after restart) by capturing the KahaDB
> store from a failed test and replaying it. It always has the bad set of
> messages.
>
>
>
> --
> View this message in context:
> http://activemq.2283324.n4.nabble.com/Message-sometimes-lost-when-transaction-open-and-broker-restarted-tp4658295p4658458.html
> Sent from the ActiveMQ - User mailing list archive at Nabble.com.
>
--
*Christian Posta*
http://www.christianposta.com/blog
twitter: @christianposta
Re: Message sometimes lost when transaction open and broker
restarted
Posted by mserrano <ma...@attivio.com>.
Thanks. I will try to. In part of my test I am using a QueueBrowser to
inspect what is on the queue. I do this to check the state at various
points to make sure it meets expectations. When I removed these checks
(which weren't completely necessary), the problem when away. So my concern
here is that since (I believe) the QueueBrowser is used for JMX inspection,
does this leave a possible, albeit small, chance that using JMX will
"corrupt" the state of a queue?
I also confirmed that this is happening before the shutdown (i.e., not an
issue with reading the KahaDB store after restart) by capturing the KahaDB
store from a failed test and replaying it. It always has the bad set of
messages.
--
View this message in context: http://activemq.2283324.n4.nabble.com/Message-sometimes-lost-when-transaction-open-and-broker-restarted-tp4658295p4658458.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.
Re: Message sometimes lost when transaction open and broker restarted
Posted by Christian Posta <ch...@gmail.com>.
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 <ma...@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