qpid-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Martin Ritchie (JIRA)" <qpid-...@incubator.apache.org>
Subject [jira] Commented: (QPID-1864) java 0-10 client sometimes releases messages in non queue order on rollback
Date Thu, 21 May 2009 11:45:45 GMT

    [ 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.AMQProtocolHandler@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.AMQProtocolSession@9b6220
pool-1-thread-1 2009-05-21 11:54:10,757 INFO [qpid.protocol] RECV: [org.apache.qpid.client.protocol.AMQProtocolHandler@53c3f5]
Frame channelId: 1, bodyFrame: org.apache.qpid.framing.ContentHeaderBody@c5122f
pool-1-thread-1 2009-05-21 11:54:10,758 INFO [qpid.protocol] RECV: [org.apache.qpid.client.protocol.AMQProtocolHandler@53c3f5]
Frame channelId: 1, bodyFrame: org.apache.qpid.framing.ContentBody@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.AMQProtocolHandler@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.ContentHeaderBody@c5122f] received in session
pool-1-thread-1 2009-05-21 11:54:10,760 INFO [qpid.protocol] RECV: [org.apache.qpid.client.protocol.AMQProtocolHandler@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.AMQProtocolHandler@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.AMQProtocolHandler@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.AMQProtocolHandler@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.AMQProtocolHandler@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.AMQProtocolHandler@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.SimpleAMQQueue@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.AMQProtocolHandler@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.AMQProtocolHandler@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.AMQProtocolSession@9b6220
pool-1-thread-3 2009-05-21 11:54:10,785 INFO [qpid.protocol] RECV: [org.apache.qpid.client.protocol.AMQProtocolHandler@53c3f5]
Frame channelId: 1, bodyFrame: org.apache.qpid.framing.ContentHeaderBody@8fbecf
pool-1-thread-3 2009-05-21 11:54:10,786 INFO [qpid.protocol] RECV: [org.apache.qpid.client.protocol.AMQProtocolHandler@53c3f5]
Frame channelId: 1, bodyFrame: org.apache.qpid.framing.ContentBody@1382926
pool-1-thread-3 2009-05-21 11:54:10,786 DEBUG [apache.qpid.client.AMQSession] Message[ContentHeader
org.apache.qpid.framing.ContentHeaderBody@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$CompositeAMQBodyBlock@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.AMQProtocolHandler@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.AMQProtocolHandler@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.SimpleAMQQueue@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.SimpleAMQQueue@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.SimpleAMQQueue@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.SimpleAMQQueue@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.AMQProtocolHandler@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.AMQProtocolHandler@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.AMQProtocolSession@9b6220
pool-1-thread-3 2009-05-21 11:54:10,802 INFO [qpid.protocol] RECV: [org.apache.qpid.client.protocol.AMQProtocolHandler@53c3f5]
Frame channelId: 1, bodyFrame: org.apache.qpid.framing.ContentHeaderBody@153b2cb
pool-1-thread-3 2009-05-21 11:54:10,803 INFO [qpid.protocol] RECV: [org.apache.qpid.client.protocol.AMQProtocolHandler@53c3f5]
Frame channelId: 1, bodyFrame: org.apache.qpid.framing.ContentBody@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$CompositeAMQBodyBlock@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$CompositeAMQBodyBlock@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$CompositeAMQBodyBlock@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$CompositeAMQBodyBlock@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:dev-subscribe@qpid.apache.org


Mime
View raw message