[
https://issues.apache.org/jira/browse/QPID-1864?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12711579#action_12711579
]
Martin Ritchie commented on QPID-1864:
--------------------------------------
Problem appears to be a race condition between the dispatcher rejecting the
message it is currently handling and the sending of the TxRollback request.
Here is the log output from a failed run. The test was augmented to print
'ROLLBACK' before calling rollback and to print out the message and the
iteration (i) where the failed message is received.
I've embedded comments in the log starting ****:
main 2009-05-21 11:54:10,751 INFO [qpid.test.client.RollbackOrderTest] ROLLBACK
main 2009-05-21 11:54:10,754 DEBUG [apache.qpid.client.AMQSession] Setting
channel flow : suspended
main 2009-05-21 11:54:10,754 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is '0x010001000000050014001400ce'
pool-1-thread-4 2009-05-21 11:54:10,755 DEBUG
[qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1,
bodyFrame: [ChannelFlowBodyImpl: active=false]
pool-1-thread-4 2009-05-21 11:54:10,755 DEBUG
[qpid.server.handler.ChannelFlowHandler] Channel.Flow for channel 1,
active=false
pool-1-thread-4 2009-05-21 11:54:10,755 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is
'0x010001000000050014001500ce'
pool-1-thread-4 2009-05-21 11:54:10,755 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent: DirectBuffer[pos=0
lim=13 cap=16: 01 00 01 00 00 00 05 00 14 00 15 00 CE]
pool-1-thread-4 2009-05-21 11:54:10,756 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent: Frame channelId:
1, bodyFrame: [ChannelFlowOkBodyImpl: active=false]
pool-1-thread-1 2009-05-21 11:54:10,754 DEBUG
[apache.qpid.framing.BasicContentHeaderProperties] Property flags: 63952
pool-1-thread-1 2009-05-21 11:54:10,756 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [BasicDeliverBodyImpl: consumerTag=1, deliveryTag=15,
redelivered=true, exchange=amq.direct, routingKey=rollback-order-test-queue]
pool-1-thread-1 2009-05-21 11:54:10,757 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (5489653)Method frame received:
[BasicDeliverBodyImpl: consumerTag=1, deliveryTag=15, redelivered=true,
exchange=amq.direct, routingKey=rollback-order-test-queue]
pool-1-thread-1 2009-05-21 11:54:10,757 DEBUG
[qpid.client.handler.BasicDeliverMethodHandler] New JmsDeliver method
received:org.apache.qpid.client.protocol.amqprotocolsess...@9b6220
pool-1-thread-1 2009-05-21 11:54:10,757 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: org.apache.qpid.framing.contentheaderb...@c5122f
pool-1-thread-1 2009-05-21 11:54:10,758 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: org.apache.qpid.framing.contentb...@2d0479
Dispatcher-Channel-1 2009-05-21 11:54:10,754 DEBUG
[qpid.client.message.AbstractJMSMessageFactory] Non-fragmented message body
(bodySize=9)
Dispatcher-Channel-1 2009-05-21 11:54:10,759 DEBUG
[qpid.client.message.AbstractJMSMessageFactory] Creating message from buffer
with position=0 and remaining=9
Dispatcher-Channel-1 2009-05-21 11:54:10,759 DEBUG
[apache.qpid.client.BasicMessageConsumer] Message is of type:
org.apache.qpid.client.message.JMSTextMessage
main 2009-05-21 11:54:10,758 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [ChannelFlowBodyImpl: active=false]
pool-1-thread-1 2009-05-21 11:54:10,758 DEBUG [apache.qpid.client.AMQSession]
Message[ContentHeader org.apache.qpid.framing.contentheaderb...@c5122f]
received in session
pool-1-thread-1 2009-05-21 11:54:10,760 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [ChannelFlowOkBodyImpl: active=false]
pool-1-thread-1 2009-05-21 11:54:10,760 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (5489653)Method frame received:
[ChannelFlowOkBodyImpl: active=false]
pool-1-thread-1 2009-05-21 11:54:10,760 DEBUG
[qpid.client.handler.ChannelFlowOkMethodHandler] Received Channel.Flow-Ok
message, active = false
main 2009-05-21 11:54:10,761 DEBUG [apache.qpid.client.AMQSession] Rejecting
delivery tag:11:SessionHC:2972067
main 2009-05-21 11:54:10,761 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is '0x0100010000000d003c005a000000000000000b01ce'
main 2009-05-21 11:54:10,762 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [BasicRejectBodyImpl: deliveryTag=11, requeue=true]
main 2009-05-21 11:54:10,762 DEBUG [qpid.client.AMQSession.Dispatcher] Set
Dispatcher Connection Stopped: Currently Started
main 2009-05-21 11:54:10,762 DEBUG [qpid.client.AMQSession.Dispatcher] Session
Pre Dispatch Queue cleared
main 2009-05-21 11:54:10,762 DEBUG [apache.qpid.client.BasicMessageConsumer]
Rejecting the messages(3) in _syncQueue (PRQ)for consumer with tag:1
main 2009-05-21 11:54:10,762 DEBUG [apache.qpid.client.AMQSession] Rejecting
Abstract message:12
main 2009-05-21 11:54:10,763 DEBUG [apache.qpid.client.AMQSession] Rejecting
delivery tag:12:SessionHC:2972067
main 2009-05-21 11:54:10,763 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is '0x0100010000000d003c005a000000000000000c01ce'
main 2009-05-21 11:54:10,763 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [BasicRejectBodyImpl: deliveryTag=12, requeue=true]
main 2009-05-21 11:54:10,763 DEBUG [apache.qpid.client.BasicMessageConsumer]
Rejected message:12
main 2009-05-21 11:54:10,764 DEBUG [apache.qpid.client.AMQSession] Rejecting
Abstract message:13
main 2009-05-21 11:54:10,764 DEBUG [apache.qpid.client.AMQSession] Rejecting
delivery tag:13:SessionHC:2972067
main 2009-05-21 11:54:10,764 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is '0x0100010000000d003c005a000000000000000d01ce'
main 2009-05-21 11:54:10,764 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [BasicRejectBodyImpl: deliveryTag=13, requeue=true]
main 2009-05-21 11:54:10,765 DEBUG [apache.qpid.client.BasicMessageConsumer]
Rejected message:13
main 2009-05-21 11:54:10,765 DEBUG [apache.qpid.client.AMQSession] Rejecting
Abstract message:14
main 2009-05-21 11:54:10,765 DEBUG [apache.qpid.client.AMQSession] Rejecting
delivery tag:14:SessionHC:2972067
main 2009-05-21 11:54:10,765 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is '0x0100010000000d003c005a000000000000000e01ce'
main 2009-05-21 11:54:10,766 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [BasicRejectBodyImpl: deliveryTag=14, requeue=true]
main 2009-05-21 11:54:10,766 DEBUG [apache.qpid.client.BasicMessageConsumer]
Rejected message:14
main 2009-05-21 11:54:10,766 DEBUG [qpid.client.AMQSession.Dispatcher] Set
Dispatcher Connection Started: Currently Stopped
main 2009-05-21 11:54:10,766 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is '0x01000100000004005a001ece'
main 2009-05-21 11:54:10,767 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [TxRollbackBodyImpl: ]
**** Dispatcher thread Reject message 15 that it was processing when the
rollback occured. NOTE this reject occurs AFTER the main thread has sent the
Rollback Request
Dispatcher-Channel-1 2009-05-21 11:54:10,767 DEBUG
[apache.qpid.client.AMQSession] Rejecting Unacked message:15
pool-1-thread-4 2009-05-21 11:54:10,770 DEBUG
[qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1,
bodyFrame: [BasicRejectBodyImpl: deliveryTag=11, requeue=true]
pool-1-thread-4 2009-05-21 11:54:10,773 DEBUG
[qpid.server.handler.BasicRejectMethodHandler] Rejecting:11: Requeue:true on
channel:1(6527985)
pool-1-thread-4 2009-05-21 11:54:10,773 DEBUG
[qpid.server.handler.BasicRejectMethodHandler] Rejecting: DT:11-(HC:5474676
ID:1 Ref:1): Requeue:true on channel:1(6527985)
pool-1-thread-4 2009-05-21 11:54:10,773 DEBUG
[qpid.server.subscription.SubscriptionImpl] Subscription:2148614 rejected
message:(HC:5474676 ID:1 Ref:1)
pool-1-thread-4 2009-05-21 11:54:10,773 DEBUG
[qpid.server.subscription.SubscriptionImpl] (2148614) checking filters for
message ((HC:5474676 ID:1 Ref:1)
pool-1-thread-4 2009-05-21 11:54:10,774 DEBUG
[qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1,
bodyFrame: [BasicRejectBodyImpl: deliveryTag=12, requeue=true]
pool-1-thread-4 2009-05-21 11:54:10,774 DEBUG
[qpid.server.handler.BasicRejectMethodHandler] Rejecting:12: Requeue:true on
channel:1(6527985)
pool-1-thread-4 2009-05-21 11:54:10,774 DEBUG
[qpid.server.handler.BasicRejectMethodHandler] Rejecting: DT:12-(HC:14846251
ID:2 Ref:1): Requeue:true on channel:1(6527985)
pool-1-thread-4 2009-05-21 11:54:10,775 DEBUG
[qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1,
bodyFrame: [BasicRejectBodyImpl: deliveryTag=13, requeue=true]
pool-1-thread-4 2009-05-21 11:54:10,775 DEBUG
[qpid.server.handler.BasicRejectMethodHandler] Rejecting:13: Requeue:true on
channel:1(6527985)
pool-1-thread-4 2009-05-21 11:54:10,775 DEBUG
[qpid.server.handler.BasicRejectMethodHandler] Rejecting: DT:13-(HC:10184846
ID:3 Ref:1): Requeue:true on channel:1(6527985)
pool-1-thread-4 2009-05-21 11:54:10,775 DEBUG
[qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1,
bodyFrame: [BasicRejectBodyImpl: deliveryTag=14, requeue=true]
pool-1-thread-4 2009-05-21 11:54:10,776 DEBUG
[qpid.server.handler.BasicRejectMethodHandler] Rejecting:14: Requeue:true on
channel:1(6527985)
pool-1-thread-4 2009-05-21 11:54:10,776 DEBUG
[qpid.server.handler.BasicRejectMethodHandler] Rejecting: DT:14-(HC:15555997
ID:4 Ref:1): Requeue:true on channel:1(6527985)
pool-1-thread-4 2009-05-21 11:54:10,776 DEBUG
[qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1,
bodyFrame: [TxRollbackBodyImpl: ]
**** Rollback Request recevied and we have 1 message in the unacked map which
is Message 5, which will correspond to Delivery Tag 15. That the Dispatcher is
in the process of rejecting
pool-1-thread-4 2009-05-21 11:54:10,776 DEBUG [apache.qpid.server.AMQChannel]
unacked map Size:1
pool-1-thread-4 2009-05-21 11:54:10,777 DEBUG [apache.qpid.server.AMQChannel]
Preparing (1) message to resend.
pool-1-thread-4 2009-05-21 11:54:10,777 DEBUG [apache.qpid.server.AMQChannel]
1(6527985) Adding unacked message(Message[(HC:27071180 ID:5 Ref:1)]: 5; ref
count: 1 DT:16) with a
queue(org.apache.qpid.server.queue.simpleamqqu...@1df5f21) for
[channel=[anonymous(13640204)(guest):1], consumerTag=1,
session=anonymous(13640204)]
pool-1-thread-4 2009-05-21 11:54:10,778 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is
'0x01000100000004005a001fce'
pool-1-thread-4 2009-05-21 11:54:10,778 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent: DirectBuffer[pos=0
lim=12 cap=16: 01 00 01 00 00 00 04 00 5A 00 1F CE]
pool-1-thread-4 2009-05-21 11:54:10,778 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent: Frame channelId:
1, bodyFrame: [TxRollbackOkBodyImpl: ]
pool-1-thread-4 2009-05-21 11:54:10,779 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is '<TRIM>
pool-1-thread-1 2009-05-21 11:54:10,779 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [TxRollbackOkBodyImpl: ]
**** : Client receives the Rollback OK
pool-1-thread-1 2009-05-21 11:54:10,782 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (5489653)Method frame received:
[TxRollbackOkBodyImpl: ]
pool-1-thread-4 2009-05-21 11:54:10,783 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent: DirectBuffer[pos=0
lim=177 cap=256: <TRIM>]
pool-1-thread-3 2009-05-21 11:54:10,784 DEBUG
[apache.qpid.framing.BasicContentHeaderProperties] Property flags: 63952
pool-1-thread-3 2009-05-21 11:54:10,784 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [BasicDeliverBodyImpl: consumerTag=1, deliveryTag=16,
redelivered=true, exchange=amq.direct, routingKey=rollback-order-test-queue]
**** Client receives the message that was in the unacked map when the
TxRollback was received.
**** Further point : Is the session not suspended here! Is that our plan we
resend all the unacked messages for the session again even though ...
**** ... the client has requested that we don't via flow = false!
pool-1-thread-3 2009-05-21 11:54:10,785 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (5489653)Method frame received:
[BasicDeliverBodyImpl: consumerTag=1, deliveryTag=16, redelivered=true,
exchange=amq.direct, routingKey=rollback-order-test-queue]
pool-1-thread-3 2009-05-21 11:54:10,785 DEBUG
[qpid.client.handler.BasicDeliverMethodHandler] New JmsDeliver method
received:org.apache.qpid.client.protocol.amqprotocolsess...@9b6220
pool-1-thread-3 2009-05-21 11:54:10,785 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: org.apache.qpid.framing.contentheaderb...@8fbecf
pool-1-thread-3 2009-05-21 11:54:10,786 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: org.apache.qpid.framing.contentb...@1382926
pool-1-thread-3 2009-05-21 11:54:10,786 DEBUG [apache.qpid.client.AMQSession]
Message[ContentHeader org.apache.qpid.framing.contentheaderb...@8fbecf]
received in session
pool-1-thread-4 2009-05-21 11:54:10,786 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent:
org.apache.qpid.server.output.amqp0_9.protocoloutputconverterimpl$compositeamqbodybl...@158cc6
**** : The dispatcher now sends the reject for DT 15
Dispatcher-Channel-1 2009-05-21 11:54:10,782 DEBUG
[apache.qpid.client.AMQSession] Rejecting delivery tag:15:SessionHC:2972067
Dispatcher-Channel-1 2009-05-21 11:54:10,788 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is
'0x0100010000000d003c005a000000000000000f01ce'
pool-1-thread-3 2009-05-21 11:54:10,788 DEBUG
[qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1,
bodyFrame: [BasicRejectBodyImpl: deliveryTag=15, requeue=true]
**** : Which is then received and the broker drops the request as there is no
DT 15 any more as it has been resent as DT 16
pool-1-thread-3 2009-05-21 11:54:10,788 DEBUG
[qpid.server.handler.BasicRejectMethodHandler] Rejecting:15: Requeue:true on
channel:1(6527985)
pool-1-thread-3 2009-05-21 11:54:10,789 WARN
[qpid.server.handler.BasicRejectMethodHandler] Dropping reject request as
message is null for tag:15
Dispatcher-Channel-1 2009-05-21 11:54:10,789 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [BasicRejectBodyImpl: deliveryTag=15, requeue=true]
Dispatcher-Channel-1 2009-05-21 11:54:10,789 DEBUG
[qpid.client.message.AbstractJMSMessageFactory] Non-fragmented message body
(bodySize=9)
Dispatcher-Channel-1 2009-05-21 11:54:10,790 DEBUG
[qpid.client.message.AbstractJMSMessageFactory] Creating message from buffer
with position=0 and remaining=9
Dispatcher-Channel-1 2009-05-21 11:54:10,790 DEBUG
[apache.qpid.client.BasicMessageConsumer] Message is of type:
org.apache.qpid.client.message.JMSTextMessage
**** : Unsuspend the session to allow delivery of messages from the queue. Even
though as mentioned above we have already sent the unacked msgs.
main 2009-05-21 11:54:10,787 DEBUG [apache.qpid.client.AMQSession] Setting
channel flow : unsuspended
main 2009-05-21 11:54:10,790 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is '0x010001000000050014001401ce'
main 2009-05-21 11:54:10,791 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [ChannelFlowBodyImpl: active=true]
pool-1-thread-1 2009-05-21 11:54:10,791 DEBUG
[qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1,
bodyFrame: [ChannelFlowBodyImpl: active=true]
pool-1-thread-1 2009-05-21 11:54:10,792 DEBUG
[qpid.server.handler.ChannelFlowHandler] Channel.Flow for channel 1, active=true
pool-1-thread-1 2009-05-21 11:54:10,792 DEBUG
[qpid.server.subscription.SubscriptionImpl] Subscription:2148614 rejected
message:(HC:5474676 ID:1 Ref:1)
pool-1-thread-1 2009-05-21 11:54:10,792 DEBUG
[qpid.server.subscription.SubscriptionImpl] (2148614) checking filters for
message ((HC:5474676 ID:1 Ref:1)
pool-1-thread-1 2009-05-21 11:54:10,792 DEBUG [apache.qpid.server.AMQChannel]
1(6527985) Adding unacked message(Message[(HC:5474676 ID:1 Ref:1)]: 1; ref
count: 1 DT:17) with a
queue(org.apache.qpid.server.queue.simpleamqqu...@1df5f21) for
[channel=[anonymous(13640204)(guest):1], consumerTag=1,
session=anonymous(13640204)]
pool-1-thread-1 2009-05-21 11:54:10,793 DEBUG
[qpid.server.subscription.SubscriptionImpl] Subscription:2148614 rejected
message:(HC:14846251 ID:2 Ref:1)
pool-1-thread-1 2009-05-21 11:54:10,793 DEBUG
[qpid.server.subscription.SubscriptionImpl] (2148614) checking filters for
message ((HC:14846251 ID:2 Ref:1)
pool-1-thread-1 2009-05-21 11:54:10,793 DEBUG [apache.qpid.server.AMQChannel]
1(6527985) Adding unacked message(Message[(HC:14846251 ID:2 Ref:1)]: 2; ref
count: 1 DT:18) with a
queue(org.apache.qpid.server.queue.simpleamqqu...@1df5f21) for
[channel=[anonymous(13640204)(guest):1], consumerTag=1,
session=anonymous(13640204)]
pool-1-thread-1 2009-05-21 11:54:10,794 DEBUG
[qpid.server.subscription.SubscriptionImpl] Subscription:2148614 rejected
message:(HC:10184846 ID:3 Ref:1)
pool-1-thread-1 2009-05-21 11:54:10,794 DEBUG
[qpid.server.subscription.SubscriptionImpl] (2148614) checking filters for
message ((HC:10184846 ID:3 Ref:1)
pool-1-thread-1 2009-05-21 11:54:10,794 DEBUG [apache.qpid.server.AMQChannel]
1(6527985) Adding unacked message(Message[(HC:10184846 ID:3 Ref:1)]: 3; ref
count: 1 DT:19) with a
queue(org.apache.qpid.server.queue.simpleamqqu...@1df5f21) for
[channel=[anonymous(13640204)(guest):1], consumerTag=1,
session=anonymous(13640204)]
pool-1-thread-1 2009-05-21 11:54:10,795 DEBUG
[qpid.server.subscription.SubscriptionImpl] Subscription:2148614 rejected
message:(HC:15555997 ID:4 Ref:1)
pool-1-thread-1 2009-05-21 11:54:10,795 DEBUG
[qpid.server.subscription.SubscriptionImpl] (2148614) checking filters for
message ((HC:15555997 ID:4 Ref:1)
pool-1-thread-1 2009-05-21 11:54:10,795 DEBUG [apache.qpid.server.AMQChannel]
1(6527985) Adding unacked message(Message[(HC:15555997 ID:4 Ref:1)]: 4; ref
count: 1 DT:20) with a
queue(org.apache.qpid.server.queue.simpleamqqu...@1df5f21) for
[channel=[anonymous(13640204)(guest):1], consumerTag=1,
session=anonymous(13640204)]
pool-1-thread-4 2009-05-21 11:54:10,795 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is
'0x010001000000050014001501ce'
pool-1-thread-4 2009-05-21 11:54:10,796 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent: DirectBuffer[pos=0
lim=13 cap=16: 01 00 01 00 00 00 05 00 14 00 15 01 CE]
pool-1-thread-3 2009-05-21 11:54:10,797 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [ChannelFlowOkBodyImpl: active=true]
pool-1-thread-3 2009-05-21 11:54:10,797 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (5489653)Method frame received:
[ChannelFlowOkBodyImpl: active=true]
pool-1-thread-3 2009-05-21 11:54:10,797 DEBUG
[qpid.client.handler.ChannelFlowOkMethodHandler] Received Channel.Flow-Ok
message, active = true
pool-1-thread-4 2009-05-21 11:54:10,797 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent: Frame channelId:
1, bodyFrame: [ChannelFlowOkBodyImpl: active=true]
main 2009-05-21 11:54:10,798 DEBUG [qpid.client.AMQSession.Dispatcher] Set
Dispatcher Connection Started: Currently Started
pool-1-thread-4 2009-05-21 11:54:10,798 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is <TRIM>
pool-1-thread-4 2009-05-21 11:54:10,799 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent: DirectBuffer[pos=0
lim=177 cap=256: <TRIM>]
pool-1-thread-3 2009-05-21 11:54:10,801 DEBUG
[apache.qpid.framing.BasicContentHeaderProperties] Property flags: 63952
pool-1-thread-3 2009-05-21 11:54:10,801 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: [BasicDeliverBodyImpl: consumerTag=1, deliveryTag=17,
redelivered=true, exchange=amq.direct, routingKey=rollback-order-test-queue]
pool-1-thread-3 2009-05-21 11:54:10,802 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (5489653)Method frame received:
[BasicDeliverBodyImpl: consumerTag=1, deliveryTag=17, redelivered=true,
exchange=amq.direct, routingKey=rollback-order-test-queue]
pool-1-thread-3 2009-05-21 11:54:10,802 DEBUG
[qpid.client.handler.BasicDeliverMethodHandler] New JmsDeliver method
received:org.apache.qpid.client.protocol.amqprotocolsess...@9b6220
pool-1-thread-3 2009-05-21 11:54:10,802 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: org.apache.qpid.framing.contentheaderb...@153b2cb
pool-1-thread-3 2009-05-21 11:54:10,803 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@53c3f5] Frame channelId: 1,
bodyFrame: org.apache.qpid.framing.contentb...@1ff2e1b
pool-1-thread-4 2009-05-21 11:54:10,803 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent:
org.apache.qpid.server.output.amqp0_9.protocoloutputconverterimpl$compositeamqbodybl...@2bfdff
pool-1-thread-4 2009-05-21 11:54:10,804 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is <TRIM>
pool-1-thread-4 2009-05-21 11:54:10,805 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent: DirectBuffer[pos=0
lim=177 cap=256: <TRIM>]
pool-1-thread-4 2009-05-21 11:54:10,806 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent:
org.apache.qpid.server.output.amqp0_9.protocoloutputconverterimpl$compositeamqbodybl...@3fa6cd
pool-1-thread-4 2009-05-21 11:54:10,806 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is <TRIM>
pool-1-thread-4 2009-05-21 11:54:10,807 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent: DirectBuffer[pos=0
lim=177 cap=256: <TRIM>]
pool-1-thread-4 2009-05-21 11:54:10,808 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent:
org.apache.qpid.server.output.amqp0_9.protocoloutputconverterimpl$compositeamqbodybl...@dfe303
pool-1-thread-4 2009-05-21 11:54:10,808 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is <TRIM>
pool-1-thread-4 2009-05-21 11:54:10,809 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent: DirectBuffer[pos=0
lim=177 cap=256: <TRIM>]
pool-1-thread-4 2009-05-21 11:54:10,810 DEBUG
[qpid.server.protocol.AMQPFastProtocolHandler] Message sent:
org.apache.qpid.server.output.amqp0_9.protocoloutputconverterimpl$compositeamqbodybl...@b0ede5
main 2009-05-21 11:54:10,801 ERROR [qpid.test.client.RollbackOrderTest] FAIL :
Run Number:3:Body:
message 5
JMS Correlation ID: null
JMS timestamp: 1242903248224
JMS expiration: 0
JMS priority: 0
JMS delivery mode: 2
JMS reply to: null
JMS Redelivered: true
JMS Destination:
direct://amq.direct/rollback-order-test-queue/rollback-order-test-queue?routingkey='rollback-order-test-queue'&durable='true'
JMS Type: null
JMS MessageID: ID:b2c6e1ac-3af5-3d9a-9b43-827c9c583df7
AMQ message number: 16
Properties:<NONE>
> java 0-10 client sometimes releases messages in non queue order on rollback
> ---------------------------------------------------------------------------
>
> Key: QPID-1864
> URL: https://issues.apache.org/jira/browse/QPID-1864
> Project: Qpid
> Issue Type: Bug
> Components: Java Client
> Affects Versions: 0.6
> Reporter: Rafael H. Schloming
> Assignee: Rafael H. Schloming
> Fix For: 0.6
>
> Attachments:
> TEST-org.apache.qpid.test.client.RollbackOrderTest.testOrderingAfterRollback.out
>
>
> On rollback, the java client sometimes releases messages from the dispatch
> thread. These messages are released in an unpredictable order relative to the
> messages released from the main thread. Also, the messages released from the
> BMC.rollbackPendingMessages() are released individually and in the opposite
> order of what would preserve queue order in a single consumer scenario.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:[email protected]
