You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Martin Ritchie (JIRA)" <qp...@incubator.apache.org> on 2008/08/26 12:27:44 UTC
[jira] Created: (QPID-1262) [AMQP-0-8/9] Client can incorrectly
report CommitOK if previous commit timed out.
[AMQP-0-8/9] Client can incorrectly report CommitOK if previous commit timed out.
---------------------------------------------------------------------------------
Key: QPID-1262
URL: https://issues.apache.org/jira/browse/QPID-1262
Project: Qpid
Issue Type: Bug
Components: Java Broker
Affects Versions: M2.1, M3
Reporter: Martin Ritchie
Summary:
As shown by the new SyncWaitTimeoutDelayTest there is a bug in AMQP. The TxCommitOk bodies do not have a correlation id so it is impossible to tell if the TxCommitOk received is for the last TxCommit sent if you have timed out a previous commit.
Attached is a log for this behaviour. As this is an AMQP bug it is unlikely we can resolve it in Qpid.
Question is does 0-10 also exhibit this behaviour.
Work around is to close the session after a commit timeout this will ensure that the TxCommitOk does not spuriously arrive on the client. It does however leave you unsure of the commit state, but presumably there was a reason you gave up waiting for the TxCommitOk and are prepared for the operation actually succeeding but never being notified about it.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (QPID-1262) [AMQP-0-8/9] Client can incorrectly
report CommitOK if previous commit timed out.
Posted by "Marnie McCormack (JIRA)" <qp...@incubator.apache.org>.
[ https://issues.apache.org/jira/browse/QPID-1262?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Marnie McCormack updated QPID-1262:
-----------------------------------
Fix Version/s: (was: M4)
Moving items not being worked on afaik out of M4 Fix Version
> [AMQP-0-8/9] Client can incorrectly report CommitOK if previous commit timed out.
> ---------------------------------------------------------------------------------
>
> Key: QPID-1262
> URL: https://issues.apache.org/jira/browse/QPID-1262
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker
> Affects Versions: M2.1, M3
> Reporter: Martin Ritchie
>
> Summary:
> As shown by the new SyncWaitTimeoutDelayTest there is a bug in AMQP. The TxCommitOk bodies do not have a correlation id so it is impossible to tell if the TxCommitOk received is for the last TxCommit sent if you have timed out a previous commit.
> Attached is a log for this behaviour. As this is an AMQP bug it is unlikely we can resolve it in Qpid.
> Question is does 0-10 also exhibit this behaviour.
> Work around is to close the session after a commit timeout this will ensure that the TxCommitOk does not spuriously arrive on the client. It does however leave you unsure of the commit state, but presumably there was a reason you gave up waiting for the TxCommitOk and are prepared for the operation actually succeeding but never being notified about it.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (QPID-1262) [AMQP-0-8/9] Client can incorrectly
report CommitOK if previous commit timed out.
Posted by "Martin Ritchie (JIRA)" <qp...@incubator.apache.org>.
[ https://issues.apache.org/jira/browse/QPID-1262?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12639391#action_12639391 ]
Martin Ritchie commented on QPID-1262:
--------------------------------------
Whilst the CommitOk from the previous loop can cause this failure when we loop the tests. I don't see how it can cause a problem when we have closed the connection between test run as happens in our test suite.
> [AMQP-0-8/9] Client can incorrectly report CommitOK if previous commit timed out.
> ---------------------------------------------------------------------------------
>
> Key: QPID-1262
> URL: https://issues.apache.org/jira/browse/QPID-1262
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker
> Affects Versions: M2.1, M3
> Reporter: Martin Ritchie
> Fix For: M4
>
>
> Summary:
> As shown by the new SyncWaitTimeoutDelayTest there is a bug in AMQP. The TxCommitOk bodies do not have a correlation id so it is impossible to tell if the TxCommitOk received is for the last TxCommit sent if you have timed out a previous commit.
> Attached is a log for this behaviour. As this is an AMQP bug it is unlikely we can resolve it in Qpid.
> Question is does 0-10 also exhibit this behaviour.
> Work around is to close the session after a commit timeout this will ensure that the TxCommitOk does not spuriously arrive on the client. It does however leave you unsure of the commit state, but presumably there was a reason you gave up waiting for the TxCommitOk and are prepared for the operation actually succeeding but never being notified about it.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (QPID-1262) [AMQP-0-8/9] Client can incorrectly
report CommitOK if previous commit timed out.
Posted by "Aidan Skinner (JIRA)" <qp...@incubator.apache.org>.
[ https://issues.apache.org/jira/browse/QPID-1262?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Aidan Skinner updated QPID-1262:
--------------------------------
Fix Version/s: M4
> [AMQP-0-8/9] Client can incorrectly report CommitOK if previous commit timed out.
> ---------------------------------------------------------------------------------
>
> Key: QPID-1262
> URL: https://issues.apache.org/jira/browse/QPID-1262
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker
> Affects Versions: M2.1, M3
> Reporter: Martin Ritchie
> Fix For: M4
>
>
> Summary:
> As shown by the new SyncWaitTimeoutDelayTest there is a bug in AMQP. The TxCommitOk bodies do not have a correlation id so it is impossible to tell if the TxCommitOk received is for the last TxCommit sent if you have timed out a previous commit.
> Attached is a log for this behaviour. As this is an AMQP bug it is unlikely we can resolve it in Qpid.
> Question is does 0-10 also exhibit this behaviour.
> Work around is to close the session after a commit timeout this will ensure that the TxCommitOk does not spuriously arrive on the client. It does however leave you unsure of the commit state, but presumably there was a reason you gave up waiting for the TxCommitOk and are prepared for the operation actually succeeding but never being notified about it.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (QPID-1262) [AMQP-0-8/9] Client can incorrectly
report CommitOK if previous commit timed out.
Posted by "Martin Ritchie (JIRA)" <qp...@incubator.apache.org>.
[ https://issues.apache.org/jira/browse/QPID-1262?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12625694#action_12625694 ]
Martin Ritchie commented on QPID-1262:
--------------------------------------
pool-2-thread-2 2008-08-26 11:17:58,253 INFO [qpid.server.store.SlowMessageStore] Done sleep for:2002:2000
pool-2-thread-2 2008-08-26 11:17:58,253 DEBUG [qpid.server.txn.LocalTransactionalContext] Performing post commit delivery
pool-2-thread-2 2008-08-26 11:17:58,254 DEBUG [qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1, bodyFrame: [ExchangeDeclareBodyImpl: ticket=0, exchange=amq.direct, type=direct, passive=false, durable=false, autoDelete=false, internal=false, nowait=true, arguments=null]
pool-2-thread-2 2008-08-26 11:17:58,255 DEBUG [server.security.access.ACLManager] Allowing user:guest for :CREATE on ExchangeDeclareBodyImpl
pool-2-thread-2 2008-08-26 11:17:58,255 DEBUG [qpid.server.handler.ExchangeDeclareHandler] Request to declare exchange of type direct with name amq.direct
pool-2-thread-2 2008-08-26 11:17:58,255 DEBUG [apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is '0x01000100000004005a0015ce'
pool-2-thread-2 2008-08-26 11:17:58,256 DEBUG [qpid.server.protocol.AMQPFastProtocolHandler] Message sent: DirectBuffer[pos=0 lim=12 cap=16: 01 00 01 00 00 00 04 00 5A 00 15 CE]
pool-2-thread-2 2008-08-26 11:17:58,256 DEBUG [qpid.server.protocol.AMQPFastProtocolHandler] Message sent: Frame channelId: 1, bodyFrame: [TxCommitOkBodyImpl: ]
pool-2-thread-3 2008-08-26 11:17:58,257 INFO [qpid.protocol] RECV: [org.apache.qpid.client.protocol.AMQProtocolHandler@159e154] Frame channelId: 1, bodyFrame: [TxCommitOkBodyImpl: ]
pool-2-thread-3 2008-08-26 11:17:58,257 DEBUG [qpid.client.protocol.AMQProtocolHandler] (22667604)Method frame received: [TxCommitOkBodyImpl: ]
The above log was generated with s slightly modified test:
POST_COMMIT_DELAY = 2000L;
SYNC_WRITE_TIMEOUT = 1000L;
loop the test() method
warn "START" // at the start of the test loop
Sleep 1s // at the end of the test loop
AMQProtocolHandler added logging to print Blocking time and expected frame
SlowMessageStore augmented to print the duration and requested sleep times
> [AMQP-0-8/9] Client can incorrectly report CommitOK if previous commit timed out.
> ---------------------------------------------------------------------------------
>
> Key: QPID-1262
> URL: https://issues.apache.org/jira/browse/QPID-1262
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker
> Affects Versions: M2.1, M3
> Reporter: Martin Ritchie
>
> Summary:
> As shown by the new SyncWaitTimeoutDelayTest there is a bug in AMQP. The TxCommitOk bodies do not have a correlation id so it is impossible to tell if the TxCommitOk received is for the last TxCommit sent if you have timed out a previous commit.
> Attached is a log for this behaviour. As this is an AMQP bug it is unlikely we can resolve it in Qpid.
> Question is does 0-10 also exhibit this behaviour.
> Work around is to close the session after a commit timeout this will ensure that the TxCommitOk does not spuriously arrive on the client. It does however leave you unsure of the commit state, but presumably there was a reason you gave up waiting for the TxCommitOk and are prepared for the operation actually succeeding but never being notified about it.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (QPID-1262) [AMQP-0-8/9] Client can incorrectly
report CommitOK if previous commit timed out.
Posted by "Martin Ritchie (JIRA)" <qp...@incubator.apache.org>.
[ https://issues.apache.org/jira/browse/QPID-1262?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12625691#action_12625691 ]
Martin Ritchie commented on QPID-1262:
--------------------------------------
main 2008-08-26 11:17:56,241 DEBUG [qpid.protocol] SEND: [org.apache.qpid.client.protocol.AMQProtocolHandler@159e154] Frame channelId: 1, bodyFrame: [TxCommitBodyImpl: ]
main 2008-08-26 11:17:56,241 DEBUG [qpid.client.protocol.AMQProtocolHandler] Blocking for:1000:org.apache.qpid.framing.TxCommitOkBody
pool-2-thread-2 2008-08-26 11:17:56,242 DEBUG [qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1, bodyFrame: org.apache.qpid.framing.ContentHeaderBody@ad157f
pool-2-thread-2 2008-08-26 11:17:56,242 DEBUG [apache.qpid.server.AMQChannel] Content header received on channel 1
pool-2-thread-2 2008-08-26 11:17:56,243 DEBUG [qpid.server.exchange.DirectExchange] Publishing message to queue [org.apache.qpid.server.queue.SimpleAMQQueue@1bfbfb8]
pool-2-thread-2 2008-08-26 11:17:56,244 DEBUG [qpid.server.txn.LocalTransactionalContext] Starting transaction on message store: org.apache.qpid.server.txn.LocalTransactionalContext@1bfa3d3
pool-2-thread-2 2008-08-26 11:17:56,244 DEBUG [qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1, bodyFrame: org.apache.qpid.framing.ContentBody@9c82f4
pool-2-thread-2 2008-08-26 11:17:56,245 DEBUG [apache.qpid.server.AMQChannel] 1(12838955)Content body received on channel 1
pool-2-thread-2 2008-08-26 11:17:56,246 DEBUG [qpid.server.queue.IncomingMessage] Delivering message 1 to [org.apache.qpid.server.queue.SimpleAMQQueue@1bfbfb8]
pool-2-thread-2 2008-08-26 11:17:56,249 DEBUG [qpid.server.protocol.AMQProtocolSession] Frame Received: Frame channelId: 1, bodyFrame: [TxCommitBodyImpl: ]
pool-2-thread-2 2008-08-26 11:17:56,249 DEBUG [qpid.server.handler.TxCommitHandler] Commit received on channel 1
pool-2-thread-2 2008-08-26 11:17:56,249 DEBUG [qpid.server.txn.LocalTransactionalContext] Committing transactional context: org.apache.qpid.server.txn.LocalTransactionalContext@1bfa3d3
pool-2-thread-2 2008-08-26 11:17:56,250 DEBUG [qpid.server.txn.TxnBuffer] Committing 1 ops to commit.:[org.apache.qpid.server.txn.StoreMessageOperation@18f1be9]
main 2008-08-26 11:17:57,245 DEBUG [test.client.timeouts.SyncWaitTimeoutDelayTest] Sleeping in session
main 2008-08-26 11:17:58,247 DEBUG [test.client.timeouts.SyncWaitTimeoutDelayTest] Done Sleep in session
main 2008-08-26 11:17:58,248 WARN [test.client.timeouts.SyncWaitTimeoutDelayTest] START
main 2008-08-26 11:17:58,248 DEBUG [apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is '0x0100010000001d0028000a00000a616d712e646972656374066469726563741000000000ce'
main 2008-08-26 11:17:58,249 DEBUG [qpid.protocol] SEND: [org.apache.qpid.client.protocol.AMQProtocolHandler@159e154] Frame channelId: 1, bodyFrame: [ExchangeDeclareBodyImpl: ticket=0, exchange=amq.direct, type=direct, passive=false, durable=false, autoDelete=false, internal=false, nowait=true, arguments=null]
main 2008-08-26 11:17:58,249 DEBUG [apache.qpid.client.BasicMessageProducer_0_8] Sending content body frames to direct://amq.direct//example.queue?routingkey='example.queue'&durable='true'
main 2008-08-26 11:17:58,249 DEBUG [apache.qpid.client.BasicMessageProducer_0_8] Sending content header frame to direct://amq.direct//example.queue?routingkey='example.queue'&durable='true'
main 2008-08-26 11:17:58,250 DEBUG [apache.qpid.framing.FieldTable] FieldTable::writeToBuffer: Writing encoded length of 0...
main 2008-08-26 11:17:58,250 DEBUG [apache.qpid.framing.FieldTable] {}
main 2008-08-26 11:17:58,250 DEBUG [apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is '0x01000100000020003c002800000a616d712e6469726563740d6578616d706c652e717565756501ce02000100000051003c00000000000000000007f9c00a746578742f706c61696e00000000000200002749443a30346535643663622d353731392d336663302d626635362d6230613933333433383435370000011bfe8510e9ce030001000000074d657373616765ce'
main 2008-08-26 11:17:58,251 DEBUG [qpid.protocol] SEND: [org.apache.qpid.client.protocol.AMQProtocolHandler@159e154] org.apache.qpid.framing.CompositeAMQDataBlock{ 0=[Frame channelId: 1, bodyFrame: [BasicPublishBodyImpl: ticket=0, exchange=amq.direct, routingKey=example.queue, mandatory=true, immediate=false]] 1=[Frame channelId: 1, bodyFrame: org.apache.qpid.framing.ContentHeaderBody@121df2a] 2=[Frame channelId: 1, bodyFrame: org.apache.qpid.framing.ContentBody@c26b16]}
main 2008-08-26 11:17:58,252 INFO [test.client.timeouts.SyncWaitTimeoutDelayTest] Calling Commit
main 2008-08-26 11:17:58,252 DEBUG [apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is '0x01000100000004005a0014ce'
main 2008-08-26 11:17:58,252 DEBUG [qpid.protocol] SEND: [org.apache.qpid.client.protocol.AMQProtocolHandler@159e154] Frame channelId: 1, bodyFrame: [TxCommitBodyImpl: ]
main 2008-08-26 11:17:58,252 DEBUG [qpid.client.protocol.AMQProtocolHandler] Blocking for:1000:org.apache.qpid.framing.TxCommitOkBody
> [AMQP-0-8/9] Client can incorrectly report CommitOK if previous commit timed out.
> ---------------------------------------------------------------------------------
>
> Key: QPID-1262
> URL: https://issues.apache.org/jira/browse/QPID-1262
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker
> Affects Versions: M2.1, M3
> Reporter: Martin Ritchie
>
> Summary:
> As shown by the new SyncWaitTimeoutDelayTest there is a bug in AMQP. The TxCommitOk bodies do not have a correlation id so it is impossible to tell if the TxCommitOk received is for the last TxCommit sent if you have timed out a previous commit.
> Attached is a log for this behaviour. As this is an AMQP bug it is unlikely we can resolve it in Qpid.
> Question is does 0-10 also exhibit this behaviour.
> Work around is to close the session after a commit timeout this will ensure that the TxCommitOk does not spuriously arrive on the client. It does however leave you unsure of the commit state, but presumably there was a reason you gave up waiting for the TxCommitOk and are prepared for the operation actually succeeding but never being notified about it.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.