Unexpected Broker Exception: [received acknowledgement with Unknown TxID]

After running OpenMessageQueue 4.0 for about nearly 2 months now without too much of a problem, I am happy.

However, today, I got a few of these exceptions on the broker.

In Summary:

1) Unknown TransactionID -1

2) Unknown Transaction xxxxxxxx

3) Transaction yyyyyy is already resolved

Here are the stack traces from the broker ( the client stack traces will follow next ):

[31/Aug/2006:14:01:21 EST] Internal Exception processing trans acknowledge [-1,11609754-10.0.21.17(9e:3c:3f:68:a2:d9)-44999-1156996820654,[consu

mer:1344620632658584576, type=NONE]]:

com.sun.messaging.jmq.jmsserver.util.BrokerException: Unexpected Broker Exception: [received acknowledgement with Unknown Transaction ID -1: ign

oring message]

[31/Aug/2006:14:01:21 EST] ERROR [B3100]: Unexpected Broker Internal Error : [-Internal Error: Invalid

Acknowledge Packet processing

notifying client

Packet: ACKNOWLEDGE(24):11616462-10.0.21.17(e9:c2:ea:ad:cb:c5)-45005-1156996881490

Magic/Version: 469754818/301 Size: 128Type: ACKNOWLEDGE(24)

Expiration: 0 Timestamp: 1156996881490

Source IP: 10.0.21.17(e9:c2:ea:ad:cb:c5) Port: 45005Sequence: 11616462

Property Offset: 88 Property Size: 0

Encryption: 0Priority: 5

Flags: A consumerID: 17764

TransactionID: -1

MessageID: 11616462-10.0.21.17(e9:c2:ea:ad:cb:c5)-45005-1156996881490

Properties:null

Message Body: 40 bytes [1344620632658584576:11609754-10.0.21.17(9e:3c:3f:68:a2:d9)-44999-1156996820654]

Internal Buffers (useDirect=false):

Fixed Header Buffer:java.nio.HeapByteBuffer[pos=0 lim=72 cap=72]

--] :

com.sun.messaging.jmq.jmsserver.util.BrokerException: Internal Error: Unable to complete processing acknowledgements in a tranaction: com.sun.m

essaging.jmq.jmsserver.util.BrokerException: Unexpected Broker Exception: [received acknowledgement with Unknown Transaction ID -1: ignoring mes

sage]

at com.sun.messaging.jmq.jmsserver.data.handlers.AckHandler.handleTransaction(AckHandler.java:404)

at com.sun.messaging.jmq.jmsserver.data.handlers.AckHandler.handle(AckHandler.java:225)

at com.sun.messaging.jmq.jmsserver.data.PacketRouter.handleMessage(PacketRouter.java:164)

at com.sun.messaging.jmq.jmsserver.service.imq.IMQConnection.readData(IMQConnection.java:1886)

at com.sun.messaging.jmq.jmsserver.service.imq.IMQConnection.process(IMQConnection.java:840)

at com.sun.messaging.jmq.jmsserver.service.imq.OperationRunnable.process(OperationRunnable.java:159)

at com.sun.messaging.jmq.jmsserver.util.pool.BasicRunnable.run(BasicRunnable.java:477)

at java.lang.Thread.run(Thread.java:595)

Caused by: com.sun.messaging.jmq.jmsserver.util.BrokerException: Unexpected Broker Exception: [received acknowledgement with Unknown Transaction

ID -1: ignoring message]

at com.sun.messaging.jmq.jmsserver.data.TransactionList.addAcknowledgement(TransactionList.java:549)

at com.sun.messaging.jmq.jmsserver.data.TransactionList.addAcknowledgement(TransactionList.java:538)

at com.sun.messaging.jmq.jmsserver.data.handlers.AckHandler.handleTransaction(AckHandler.java:397)

... 7 more

[31/Aug/2006:14:01:54 EST] Internal Exception processing trans acknowledge [1344620679964220928,11611493-10.0.21.17(f9:b6:69:b7:6d:72)-45001-115

6996835639,[consumer:1344620632658568960, type=NONE]]:

com.sun.messaging.jmq.jmsserver.util.BrokerException: Unexpected Broker Exception: [received acknowledgement with Unknown Transaction ID 1344620

679964220928: ignoring message]

[31/Aug/2006:14:01:54 EST] Internal Exception processing trans acknowledge [1344620679964306688,11611319-10.0.21.17(f9:b6:69:b7:6d:72)-45001-115

6996834641,[consumer:1344620632658492160, type=NONE]]:

com.sun.messaging.jmq.jmsserver.util.BrokerException: Unexpected Broker Exception: [received acknowledgement with Unknown Transaction ID 1344620

679964306688: ignoring message]

[31/Aug/2006:14:01:54 EST] ERROR [B3100]: Unexpected Broker Internal Error : [-Internal Error: Invalid

Acknowledge Packet processing

notifying client

Packet: ACKNOWLEDGE(24):11620037-10.0.21.17(c5:cd:9b:d7:de:a9)-45003-1156996913862

Magic/Version: 469754818/301 Size: 128Type: ACKNOWLEDGE(24)

Expiration: 0 Timestamp: 1156996913862

Source IP: 10.0.21.17(c5:cd:9b:d7:de:a9) Port: 45003Sequence: 11620037

Property Offset: 88 Property Size: 0

Encryption: 0Priority: 5

Flags: A consumerID: 17763

TransactionID: 1344620679964220928

MessageID: 11620037-10.0.21.17(c5:cd:9b:d7:de:a9)-45003-1156996913862

Properties:null

Message Body: 40 bytes [1344620632658568960:11611493-10.0.21.17(f9:b6:69:b7:6d:72)-45001-1156996835639]

Internal Buffers (useDirect=false):

Fixed Header Buffer:java.nio.HeapByteBuffer[pos=0 lim=72 cap=72]

--] :

com.sun.messaging.jmq.jmsserver.util.BrokerException: Internal Error: Unable to complete processing acknowledgements in a tranaction: com.sun.m

essaging.jmq.jmsserver.util.BrokerException: Unexpected Broker Exception: [received acknowledgement with Unknown Transaction ID 1344620679964220

928: ignoring message]

at com.sun.messaging.jmq.jmsserver.data.handlers.AckHandler.handleTransaction(AckHandler.java:404)

at com.sun.messaging.jmq.jmsserver.data.handlers.AckHandler.handle(AckHandler.java:225)

at com.sun.messaging.jmq.jmsserver.data.PacketRouter.handleMessage(PacketRouter.java:164)

at com.sun.messaging.jmq.jmsserver.service.imq.IMQConnection.readData(IMQConnection.java:1886)

at com.sun.messaging.jmq.jmsserver.service.imq.IMQConnection.process(IMQConnection.java:840)

at com.sun.messaging.jmq.jmsserver.service.imq.OperationRunnable.process(OperationRunnable.java:159)

at com.sun.messaging.jmq.jmsserver.util.pool.BasicRunnable.run(BasicRunnable.java:477)

at java.lang.Thread.run(Thread.java:595)

Caused by: com.sun.messaging.jmq.jmsserver.util.BrokerException: Unexpected Broker Exception: [received acknowledgement with Unknown Transaction

ID 1344620679964220928: ignoring message]

at com.sun.messaging.jmq.jmsserver.data.TransactionList.addAcknowledgement(TransactionList.java:549)

at com.sun.messaging.jmq.jmsserver.data.TransactionList.addAcknowledgement(TransactionList.java:538)

at com.sun.messaging.jmq.jmsserver.data.handlers.AckHandler.handleTransaction(AckHandler.java:397)

... 7 more

[31/Aug/2006:14:01:54 EST] ERROR [B3100]: Unexpected Broker Internal Error : [-Internal Error: Invalid

Acknowledge Packet processing

notifying client

Packet: ACKNOWLEDGE(24):11620036-10.0.21.17(d1:8d:1f:9e:81:78)-44993-1156996913843

Magic/Version: 469754818/301 Size: 128Type: ACKNOWLEDGE(24)

Expiration: 0 Timestamp: 1156996913843

Source IP: 10.0.21.17(d1:8d:1f:9e:81:78) Port: 44993Sequence: 11620036

Property Offset: 88 Property Size: 0

Encryption: 0Priority: 5

Flags: A consumerID: 17375

TransactionID: 1344620679964306688

MessageID: 11620036-10.0.21.17(d1:8d:1f:9e:81:78)-44993-1156996913843

Properties:null

Message Body: 40 bytes [1344620632658492160:11611319-10.0.21.17(f9:b6:69:b7:6d:72)-45001-1156996834641]

Internal Buffers (useDirect=false):

Fixed Header Buffer:java.nio.HeapByteBuffer[pos=0 lim=72 cap=72]

--] :

com.sun.messaging.jmq.jmsserver.util.BrokerException: Internal Error: Unable to complete processing acknowledgements in a tranaction: com.sun.m

essaging.jmq.jmsserver.util.BrokerException: Unexpected Broker Exception: [received acknowledgement with Unknown Transaction ID 1344620679964306

688: ignoring message]

at com.sun.messaging.jmq.jmsserver.data.handlers.AckHandler.handleTransaction(AckHandler.java:404)

at com.sun.messaging.jmq.jmsserver.data.handlers.AckHandler.handle(AckHandler.java:225)

at com.sun.messaging.jmq.jmsserver.data.PacketRouter.handleMessage(PacketRouter.java:164)

at com.sun.messaging.jmq.jmsserver.service.imq.IMQConnection.readData(IMQConnection.java:1886)

at com.sun.messaging.jmq.jmsserver.service.imq.IMQConnection.process(IMQConnection.java:840)

at com.sun.messaging.jmq.jmsserver.service.imq.OperationRunnable.process(OperationRunnable.java:159)

at com.sun.messaging.jmq.jmsserver.util.pool.BasicRunnable.run(BasicRunnable.java:477)

at java.lang.Thread.run(Thread.java:595)

Caused by: com.sun.messaging.jmq.jmsserver.util.BrokerException: Unexpected Broker Exception: [received acknowledgement with Unknown Transaction

ID 1344620679964306688: ignoring message]

at com.sun.messaging.jmq.jmsserver.data.TransactionList.addAcknowledgement(TransactionList.java:549)

at com.sun.messaging.jmq.jmsserver.data.TransactionList.addAcknowledgement(TransactionList.java:538)

at com.sun.messaging.jmq.jmsserver.data.handlers.AckHandler.handleTransaction(AckHandler.java:397)

... 7 more

[31/Aug/2006:14:02:01 EST] ERROR Transaction ID 1344620679964306688 has already been resolved. Ignoring request: ROLLBACK_TRANSACTION(48). Last

state ofthis transaction: guest@null:COMMITED(6) broker will not notify the client

Here are the stack traces from the client:

2006-08-31 14:03:31,045 [imqConsumerReader-1-1344620610360452864-1] ERROR - Unable to commit JMS transaction.

com.sun.messaging.jms.JMSException: [C4000]: Packet acknowledge failed. user=guest, broker=10.0.21.94:7676(37111)

at com.sun.messaging.jmq.jmsclient.ProtocolHandler.writePacketWithAck(ProtocolHandler.java:694)

at com.sun.messaging.jmq.jmsclient.ProtocolHandler.writePacketWithAck(ProtocolHandler.java:555)

at com.sun.messaging.jmq.jmsclient.ProtocolHandler.writePacketWithReply(ProtocolHandler.java:410)

at com.sun.messaging.jmq.jmsclient.ProtocolHandler.startTransaction(ProtocolHandler.java:2599)

at com.sun.messaging.jmq.jmsclient.ProtocolHandler.startTransaction(ProtocolHandler.java:2538)

at com.sun.messaging.jmq.jmsclient.Transaction.startTransaction(Transaction.java:521)

at com.sun.messaging.jmq.jmsclient.Transaction.startNewLocalTransaction(Transaction.java:503)

at com.sun.messaging.jmq.jmsclient.Transaction.commit(Transaction.java:138)

at com.sun.messaging.jmq.jmsclient.SessionImpl.commit(SessionImpl.java:1879)

at softgame.gateway.connectors.http.AbstractMessageNotificationListener.onMessage(AbstractMessageNotificationListener.java:155)

at com.sun.messaging.jmq.jmsclient.MessageConsumerImpl.deliverAndAcknowledge(MessageConsumerImpl.java:300)

at com.sun.messaging.jmq.jmsclient.MessageConsumerImpl.onMessage(MessageConsumerImpl.java:263)

at com.sun.messaging.jmq.jmsclient.SessionReader.deliver(SessionReader.java:94)

at com.sun.messaging.jmq.jmsclient.ConsumerReader.run(ConsumerReader.java:174)

at java.lang.Thread.run(Thread.java:595)

2006-08-31 14:03:38,019 [imqConsumerReader-3-1344620610360476928-3] ERROR - Unable to process notification

com.sun.messaging.jms.JMSException: [SEND_REPLY(9)] [C4036]: A server error occurred. :[500] transaction failed: Unexpected Broker Exception: [r

eceived message with Unknown Transaction ID -1: ignoring message] user=guest, broker=10.0.21.94:7676(37111)

at com.sun.messaging.jmq.jmsclient.ProtocolHandler.throwServerErrorException(ProtocolHandler.java:3764)

at com.sun.messaging.jmq.jmsclient.ProtocolHandler.writeJMSMessage(ProtocolHandler.java:1900)

at com.sun.messaging.jmq.jmsclient.WriteChannel.sendWithFlowControl(WriteChannel.java:141)

at com.sun.messaging.jmq.jmsclient.WriteChannel.writeJMSMessage(WriteChannel.java:94)

at com.sun.messaging.jmq.jmsclient.Transaction.send(Transaction.java:431)

at com.sun.messaging.jmq.jmsclient.SessionImpl.writeJMSMessage(SessionImpl.java:747)

at com.sun.messaging.jmq.jmsclient.MessageProducerImpl.writeJMSMessage(MessageProducerImpl.java:191)

at com.sun.messaging.jmq.jmsclient.MessageProducerImpl.writeJMSMessage(MessageProducerImpl.java:180)

at com.sun.messaging.jmq.jmsclient.MessageProducerImpl.send(MessageProducerImpl.java:561)

at com.sun.messaging.jmq.jmsclient.QueueSenderImpl.send(QueueSenderImpl.java:90)

at softgame.gateway.connectors.http.MessageNotificationListener.processNotification(MessageNotificationListener.java:194)

at softgame.gateway.connectors.http.AbstractMessageNotificationListener.onMessage(AbstractMessageNotificationListener.java:111)

at com.sun.messaging.jmq.jmsclient.MessageConsumerImpl.deliverAndAcknowledge(MessageConsumerImpl.java:300)

at com.sun.messaging.jmq.jmsclient.MessageConsumerImpl.onMessage(MessageConsumerImpl.java:263)

at com.sun.messaging.jmq.jmsclient.SessionReader.deliver(SessionReader.java:94)

at com.sun.messaging.jmq.jmsclient.ConsumerReader.run(ConsumerReader.java:174)

at java.lang.Thread.run(Thread.java:595)

[13415 byte] By [j.salvo] at [2007-11-26 9:50:45]
# 1

More stack traces:

[31/Aug/2006:14:02:23 EST] ERROR [B3100]: Unexpected Broker Internal Error : [Unknown transaction: -1(-1) broker will not notify the client Ign

oring ROLLBACK_TRANSACTION(48)

Packet: ROLLBACK_TRANSACTION(48):11623409-10.0.21.17(cb:a0:7d:e5:a9:64)-45009-1156996943383

Magic/Version: 469754818/301 Size: 112Type: ROLLBACK_TRANSACTION(48)

Expiration: 0 Timestamp: 1156996943383

Source IP: 10.0.21.17(cb:a0:7d:e5:a9:64) Port: 45009Sequence: 11623409

Property Offset: 76 Property Size: 36

Encryption: 0Priority: 5

Flags:consumerID: 0

TransactionID: 0

MessageID: 11623409-10.0.21.17(cb:a0:7d:e5:a9:64)-45009-1156996943383

Properties: {JMQTransactionID=-1}

Message Body: 0 bytes

Internal Buffers (useDirect=false):

Fixed Header Buffer:java.nio.HeapByteBuffer[pos=0 lim=72 cap=72]

]

[31/Aug/2006:14:02:26 EST] ERROR [B3100]: Unexpected Broker Internal Error : [Unknown transaction: -1(-1) broker will not notify the client Ign

oring ROLLBACK_TRANSACTION(48)

Packet: ROLLBACK_TRANSACTION(48):11623834-10.0.21.17(9e:25:43:8f:69:91)-44987-1156996946906

Magic/Version: 469754818/301 Size: 112Type: ROLLBACK_TRANSACTION(48)

Expiration: 0 Timestamp: 1156996946906

Source IP: 10.0.21.17(9e:25:43:8f:69:91) Port: 44987Sequence: 11623834

Property Offset: 76 Property Size: 36

Encryption: 0Priority: 5

Flags:consumerID: 0

TransactionID: 0

MessageID: 11623834-10.0.21.17(9e:25:43:8f:69:91)-44987-1156996946906

Properties: {JMQTransactionID=-1}

Message Body: 0 bytes

Internal Buffers (useDirect=false):

Fixed Header Buffer:java.nio.HeapByteBuffer[pos=0 lim=72 cap=72]

]

jsalvo at 2007-7-7 1:02:26 > top of Java-index,Application & Integration Servers,Sun Java System Message Queue...
# 2

One possible scenario for the exceptions to occur is that a fail-over occurred (client reconnected to the broker) in an open transaction.

The section "Handling Exceptions When Failover Occurs" of the following doc provides some information and examples to handle situation like this:

http://docs.sun.com/app/docs/doc/819-4469/6n6kb5cs3?a=view#gczqs

MQ 4.1 will improve the transaction implementation to minimize the requirement for applications to handle exceptions.

chiaming

chiamingyang at 2007-7-7 1:02:26 > top of Java-index,Application & Integration Servers,Sun Java System Message Queue...
# 3
Thanks for the reply. Looking forward to OMQ 4.1. Do you know when it is scheduled for public release ?Also, is there currently a way to turn-on log on the client side, so that when things such as failovers, client exceptions, are logged ?
jsalvo at 2007-7-7 1:02:26 > top of Java-index,Application & Integration Servers,Sun Java System Message Queue...
# 4
There is no official release date for MQ4.1 yet. It contains high-availability feature and requires intensive verification.Below is a link to the MQ (4.0) client runtime logging feature
chiamingyang at 2007-7-7 1:02:26 > top of Java-index,Application & Integration Servers,Sun Java System Message Queue...
# 5

I have this happen today again. As you mentioned, it appears like the problem was happening during Session.commit().

I also found some additional stack traces on the server:

[26/Sep/2006:12:05:39 EST] [B3100]: Unexpected Broker Internal Error : [Internal error Unable to find producer 1172640023947176704

checking if producer was removed recently Producer[1172640023947176704]:1159236337502:Producer closed requested:

connection: 1172640023947168000

producerID: 1172640023947176704

request sysmsgid message: 4247204-10.0.21.1(f6:2a:4:91:74:43)-56630-1159236322116]

[26/Sep/2006:12:05:39 EST] [B3100]: Unexpected Broker Internal Error : [Internal error Unable to find producer 1172640023981085440

checking if producer was removed recently Producer[1172640023981085440]:1159236339506:Producer closed requested:

connection: 1172640023981076480

producerID: 1172640023981085440

request sysmsgid message: 1394890-10.0.21.4(dd:d6:3a:40:e9:24)-60258-1159236321823]

[26/Sep/2006:12:05:39 EST] [B3100]: Unexpected Broker Internal Error : [Internal error Unable to find producer 1172640023981085440

checking if producer was removed recently Producer[1172640023981085440]:1159236339506:Producer closed requested:

connection: 1172640023981076480

producerID: 1172640023981085440

request sysmsgid message: 1394890-10.0.21.4(dd:d6:3a:40:e9:24)-60258-1159236321823]

[26/Sep/2006:12:05:39 EST] [B3100]: Unexpected Broker Internal Error : [Internal error Unable to find producer 1172640023981085440

checking if producer was removed recently Producer[1172640023981085440]:1159236339506:Producer closed requested:

connection: 1172640023981076480

producerID: 1172640023981085440

request sysmsgid message: 1394890-10.0.21.4(dd:d6:3a:40:e9:24)-60258-1159236321823]

[26/Sep/2006:12:05:39 EST] [B3100]: Unexpected Broker Internal Error : [Internal error Unable to find producer 1172640023981085440

checking if producer was removed recently Producer[1172640023981085440]:1159236339506:Producer closed requested:

connection: 1172640023981076480

producerID: 1172640023981085440

request sysmsgid message: 1394890-10.0.21.4(dd:d6:3a:40:e9:24)-60258-1159236321823]

[26/Sep/2006:12:05:39 EST] [B3100]: Unexpected Broker Internal Error : [Internal error Unable to find producer 1172640023981085440

checking if producer was removed recently Producer[1172640023981085440]:1159236339506:Producer closed requested:

connection: 1172640023981076480

producerID: 1172640023981085440

request sysmsgid message: 1394890-10.0.21.4(dd:d6:3a:40:e9:24)-60258-1159236321823]

jsalvo at 2007-7-7 1:02:26 > top of Java-index,Application & Integration Servers,Sun Java System Message Queue...