activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Hans Bausewein (JIRA)" <j...@apache.org>
Subject [jira] Issue Comment Edited: (AMQ-1983) Async error occurred - Slave broker out of sync with master
Date Wed, 22 Oct 2008 08:40:52 GMT

    [ https://issues.apache.org/activemq/browse/AMQ-1983?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=46665#action_46665
] 

hansb edited comment on AMQ-1983 at 10/22/08 1:39 AM:
---------------------------------------------------------------

This is the start and end of the XA transactions with that XID in the JBoss server log:

2008-10-21 18:27:09,412 DEBUG [org.apache.activemq.TransactionContext] Started XA transaction:
XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f313530383400000000000000000000000000000000000000000000000000000000000000000000000000:
31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
...........
2008-10-21 18:27:09,457 DEBUG [org.apache.activemq.TransactionContext] Started XA transaction:
XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f313530383400000000000000000000000000000000000000000000000000000000000000000000000000:
31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000

.................
2008-10-21 18:27:09,459 DEBUG [org.apache.activemq.ActiveMQSession] ID:master.cluster-49988-1224605035095-0:42:346
sending message: ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId =
ID:master.cluster-49988-1224605035095-0:42:346:1:1, originalDestination = null, originalTransactionId
= null, producerId = ID:master.cluster-49988-1224605035095-0:42:346:1, destination = topic://topic.PRE_CLIENT_OUT,
transactionId = XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f313530383400000000000000000000000000000000000000000000000000000000000000000000000000:
31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000,
expiration = 0, timestamp = 1224606429459, arrival = 0, brokerInTime = 0, brokerOutTime =
0, correlationId = null, replyTo = null, persistent = true, type = null, priority = 4, groupID
= null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content
= null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0,
properties = null, readOnlyProperties = true, readOnlyBody = true, droppable = false, text
=
 
2008-10-21 18:27:09,478 DEBUG [org.apache.activemq.ActiveMQSession] ID:master.cluster-49988-1224605035095-0:42:346
sending message: ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId =
ID:master.cluster-49988-1224605035095-0:42:346:2:1, originalDestination = null, originalTransactionId
= null, producerId = ID:master.cluster-49988-1224605035095-0:42:346:2, destination = queue://queue.CLIENT_OUT,
transactionId = XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f313530383400000000000000000000000000000000000000000000000000000000000000000000000000:
31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000,
expiration = 0, timestamp = 1224606429478, arrival = 0, brokerInTime = 0, brokerOutTime =
0, correlationId = null, replyTo = null, persistent = true, type = null, priority = 4, groupID
= null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content
= null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0,
properties = {tnx435=true}, readOnlyProperties = true, readOnlyBody = true, droppable = false,
text =
.............

2008-10-21 18:27:09,730 DEBUG [org.apache.activemq.TransactionContext] Ended XA transaction:
XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f313530383400000000000000000000000000000000000000000000000000000000000000000000000000:
31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
2008-10-21 18:27:09,730 DEBUG [org.apache.activemq.TransactionContext] End: XidImpl[FormatId=257,
GlobalId=mcfadden.marketxs.com/15084, BranchQual=1, localId=15084]
2008-10-21 18:27:09,730 DEBUG [org.apache.activemq.TransactionContext] Ended XA transaction:
XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f313530383400000000000000000000000000000000000000000000000000000000000000000000000000:
31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000

Apparently there are 2 transactions with the same transaction id!

For different queues, though.

      was (Author: hansb):
    This is the start and end of the XA transactions with that XID in the JBoss server log:

2008-10-21 18:27:09,412 DEBUG [org.apache.activemq.TransactionContext] Started XA transaction:
XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f313530383400000000000000000000000000000000000000000000000000000000000000000000000000:
31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
...........
2008-10-21 18:27:09,457 DEBUG [org.apache.activemq.TransactionContext] Started XA transaction:
XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f313530383400000000000000000000000000000000000000000000000000000000000000000000000000:
31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000

.................
2008-10-21 18:27:09,459 DEBUG [org.apache.activemq.ActiveMQSession] ID:master.cluster-49988-1224605035095-0:42:346
sending message: ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId =
ID:master.cluster-49988-1224605035095-0:42:346:1:1, originalDestination = null, originalTransactionId
= null, producerId = ID:master.cluster-49988-1224605035095-0:42:346:1, destination = topic://topic.PRE_CLIENT_OUT,
transactionId = XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f313530383400000000000000000000000000000000000000000000000000000000000000000000000000:
31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000,
expiration = 0, timestamp = 1224606429459, arrival = 0, brokerInTime = 0, brokerOutTime =
0, correlationId = null, replyTo = null, persistent = true, type = null, priority = 4, groupID
= null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content
= null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0,
properties = null, readOnlyProperties = true, readOnlyBody = true, droppable = false, text
=
 
2008-10-21 18:27:09,478 DEBUG [org.apache.activemq.ActiveMQSession] ID:master.cluster-49988-1224605035095-0:42:346
sending message: ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId =
ID:master.cluster-49988-1224605035095-0:42:346:2:1, originalDestination = null, originalTransactionId
= null, producerId = ID:master.cluster-49988-1224605035095-0:42:346:2, destination = queue://queue.CLIENT_OUT,
transactionId = XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f313530383400000000000000000000000000000000000000000000000000000000000000000000000000:
31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000,
expiration = 0, timestamp = 1224606429478, arrival = 0, brokerInTime = 0, brokerOutTime =
0, correlationId = null, replyTo = null, persistent = true, type = null, priority = 4, groupID
= null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content
= null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0,
properties = {tnx435=true}, readOnlyProperties = true, readOnlyBody = true, droppable = false,
text =
.............

2008-10-21 18:27:09,730 DEBUG [org.apache.activemq.TransactionContext] Ended XA transaction:
XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f3135303834000000000000000000000000000000000000000000000000000000000
00000000000000000:31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
2008-10-21 18:27:09,730 DEBUG [org.apache.activemq.TransactionContext] End: XidImpl[FormatId=257,
GlobalId=mcfadden.marketxs.com/15084, BranchQual=1, localId=15084]
2008-10-21 18:27:09,730 DEBUG [org.apache.activemq.TransactionContext] Ended XA transaction:
XID:257:6d6366616464656e2e6d61726b657478732e636f6d2f313530383400000000000000000000000000000000000000000000000000000000000000000000000000:
31000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000

Apparently there are 2 transactions with the same transaction id!

For different queues, though.
  
> Async error occurred - Slave broker out of sync with master
> -----------------------------------------------------------
>
>                 Key: AMQ-1983
>                 URL: https://issues.apache.org/activemq/browse/AMQ-1983
>             Project: ActiveMQ
>          Issue Type: Bug
>          Components: Broker
>    Affects Versions: 5.2.0
>         Environment: java version "1.6.0_07"
> Client is a JBoss 4.2.3.GA cluster using the ActiveMQ resource adapter (from RC2)
> ActiveMQ 5.3.0  rev 706043 in pure master/slave setup
>            Reporter: Hans Bausewein
>         Attachments: activemq-master.log.gz, activemq-slave.log.gz, activemqjee-0.0.8-src.tar.gz
>
>
> I have tried to reduce the real-life problem to something smaller. See activemqjee-0.0.8.tar.gz
> It's a MDB that forwards a message to another queue. 
> What I did:
> - send some messages to queue.A (I did 10 at a time, using the webconsole setting Persistent
Delivery)
> - the MDB sends each message to queue.B
> - if a reply queue was set in the message, the MDB sends a reply
> On queue.B is an MDB that just received and logs the message.
> Logged on the master:
> {code}
> 2008-10-19 18:39:54,114 [127.0.0.1:43972] DEBUG AMQMessageStore                - Journalled
transacted message add for:
>    ID:selten.cluster-40744-1224434310420-0:2:4:1:1, at: offset = 90045, file = 1, size
= 429, type = 1
> ......
> 2008-10-19 18:39:54,278 [127.0.0.1:43972] DEBUG AMQMessageStore                - Transacted
message add commit for:
>    ID:selten.cluster-40744-1224434310420-0:2:4:1:1, at: offset = 90045, file = 1, size
= 429, type = 1
> ......
> 2008-10-19 18:39:54,305 [127.0.0.1:43962] ERROR MasterBroker                   - Slave
Failed
> javax.jms.JMSException: Unmatched acknowledege: MessageAck {commandId = 1031, responseRequired
= true, ackType = 2, 
>   consumerId = ID:selten.cluster-40744-1224434310420-0:0:-1:2, firstMessageId = 
> ID:selten.cluster-40744-1224434310420-0:2:4:1:1, lastMessageId = ID:selten.cluster-40744-1224434310420-0:2:4:1:1,

>   destination = queue://queue.B, 
> transactionId = XID:131075:312d2d32613062356562303a613535653a34386662363236643a313135:2d32613062356562303a613535653a34386662363236643a313136,
>  messageCount = 1}; Could not find Message-ID ID:selten.cluster-40744-1224434310420-0:2:4:1:1
in dispatched-list (start of ack)
>         at org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:438)
>         at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:188)
>         at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:373)
>         at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:462)
> {code}
> Logged on the slave:
> {code}
> 2008-10-19 18:39:54,112 [.cluster#1] DEBUG AMQMessageStore                - Journalled
transacted message add for: ID:selten.cluster-40744-1224434310420-0:2:4:1:1, at: offset =
90045, file = 1, size = 429, type = 1
> ......
> 2008-10-19 18:39:54,241 [.cluster#1] DEBUG AMQMessageStore                - Transacted
message add commit for: ID:selten.cluster-40744-1224434310420-0:2:4:1:1, at: offset = 90045,
file = 1, size = 429, type = 1
> ......
> 2008-10-19 18:39:54,288 [.cluster#1] ERROR Service                        - Async error
occurred: javax.jms.JMSException: Slave broker out of sync with master: 
>   Dispatched message (ID:selten.cluster-40744-1224434310420-0:2:4:1:1) was not in the
pending list for queue.B
>   javax.jms.JMSException: Slave broker out of sync with master: Dispatched message 
> (ID:selten.cluster-40744-1224434310420-0:2:4:1:1) was not in the pending list for queue.B
>         at org.apache.activemq.broker.region.PrefetchSubscription.processMessageDispatchNotification(PrefetchSubscription.java:175)
>         at org.apache.activemq.broker.region.AbstractRegion.processDispatchNotification(AbstractRegion.java:414)
>         at org.apache.activemq.broker.region.RegionBroker.processDispatchNotification(RegionBroker.java:585)
> {code}
> I could not consistently reproduce it with a single JBoss server running. I've sent a
few 100 messages without any problem.
> I've tested both 5.2.0-RC2 and 5.3.0-SNAPSHOT (rev 706043).

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message