You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Alex Rudyy (JIRA)" <ji...@apache.org> on 2012/05/25 15:50:23 UTC
[jira] [Commented] (QPID-4018) AMQP 0-10:
AMQSession.getQueueDepth() timed out because of "Received a response to a
command that's no longer valid"
[ https://issues.apache.org/jira/browse/QPID-4018?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13283415#comment-13283415 ]
Alex Rudyy commented on QPID-4018:
----------------------------------
The test application was sending messages with producer flow control on in the main thread. An auxiliary thread was run in background to check whether flow is blocked on the sending session. In case of blocked flow, the auxiliary thread was using the sending session to query queue to get the number of published messages to consume that number of messages in order to unblock the flow.
According to the attached client log, the flow blocking commands (MessageSetFlowMode(destination=, flowMode=CREDIT), MessageStop(destination=)) was received and blocked the flow when the session was in a process of sending a message and internal session command buffer was full. As result of it, the sending session sent SessionFlush(completed=true) and was put into waiting state until buffer is not full. That released the commandsLock lock and allowed the monitoring thread to send the QueueQuery command before the MessageTransfer command was sent.
As result of it the command with greater ID (QueueQuery, id=105358 ) was sent if front of the command with lower ID (MessageTransfer, id=105357)
Server on receiving QueueQuery command assigned this command a different id (105357) that it was sent with. The ExecutionResult was sent with the server id and client could not find the corresponding entry in the results Future map and thrown an Exception.
{noformat}
2012-05-25 13:03:20,459 DEBUG [Connection] SEND: [conn:6490832e] ch=0 id=105358 QueueQuery(queue=quotaTestDestination)
2012-05-25 13:03:20,459 DEBUG [Connection] FLUSH: [conn:6490832e]
2012-05-25 13:03:20,459 DEBUG [Connection] FLUSH: [conn:6490832e]
2012-05-25 13:03:20,459 DEBUG [Connection] RECV: [conn:6490832e] ch=1 SessionCommandPoint(commandId=0, commandOffset=0)
2012-05-25 13:03:20,459 DEBUG [BasicMessageProducer_0_10] MessageProducer org.apache.qpid.client.BasicMessageProducer_0_10@44da44a6 using publish mode : ASYN
C_PUBLISH_ALL
2012-05-25 13:03:20,460 DEBUG [Connection] RECV: [conn:6490832e] ch=1 MessageSetFlowMode(destination=, flowMode=CREDIT)
2012-05-25 13:03:20,460 DEBUG [Session] ID: [1] 0
2012-05-25 13:03:20,460 DEBUG [Session] ssn:"563f2d63-1c1f-4e45-abd9-0ce46316ed85" processed([0,0]) -1 -1
2012-05-25 13:03:20,460 DEBUG [Session] {}
2012-05-25 13:03:20,460 DEBUG [Connection] RECV: [conn:6490832e] ch=1 SessionFlush(completed=true)
2012-05-25 13:03:20,460 DEBUG [Connection] SEND: [conn:6490832e] ch=1 SessionCompleted(commands={[0, 0]})
2012-05-25 13:03:20,460 DEBUG [Connection] FLUSH: [conn:6490832e]
2012-05-25 13:03:20,460 DEBUG [Connection] RECV: [conn:6490832e] ch=1 MessageStop(destination=)
2012-05-25 13:03:20,460 DEBUG [Session] ID: [1] 1
2012-05-25 13:03:20,460 DEBUG [Session] ssn:"563f2d63-1c1f-4e45-abd9-0ce46316ed85" processed([1,1]) 0 0
2012-05-25 13:03:20,460 DEBUG [Session] {[0, 0]}
2012-05-25 13:03:20,460 DEBUG [Session] ssn:"153d0147-16a9-48c3-8e3c-846d05ab6fc3" waiting for result: Future(class org.apache.qpid.transport.QueueQueryResul
t)
2012-05-25 13:03:20,460 DEBUG [Connection] SEND: [conn:6490832e] ch=0 id=105357 MessageTransfer(destination=amq.direct, acceptMode=NONE, acquireMode=PRE_ACQU
IRED)
DeliveryProperties(priority=MEDIUM, deliveryMode=PERSISTENT, timestamp=1337947400319, exchange=amq.direct, routingKey=quotaTestDestination)
MessageProperties(contentLength=10000, messageId=ddea0af9-520c-314b-87a3-24ff1da9e4ef, contentType=text/plain, userId=[B@4a0ece36)
body="xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"...
2012-05-25 13:03:20,460 DEBUG [Connection] FLUSH: [conn:6490832e]
2012-05-25 13:03:20,460 DEBUG [AMQDestination] Based on :////?routingkey='' the selected destination syntax is BURL
2012-05-25 13:03:20,460 DEBUG [Connection] RECV: [conn:6490832e] ch=1 SessionTimeout(timeout=0)
2012-05-25 13:03:20,461 DEBUG [Connection] RECV: [conn:6490832e] ch=0 SessionCompleted(commands=[105213, 105348])
2012-05-25 13:03:20,461 DEBUG [Session] ssn:"153d0147-16a9-48c3-8e3c-846d05ab6fc3" complete(105213, 105348)
2012-05-25 13:03:20,461 DEBUG [Session] ssn:"153d0147-16a9-48c3-8e3c-846d05ab6fc3" commands remaining: 11
2012-05-25 13:03:20,485 DEBUG [Connection] RECV: [conn:6490832e] ch=1 SessionCompleted(commands=[0, 0])
2012-05-25 13:03:20,485 DEBUG [Session] ssn:"563f2d63-1c1f-4e45-abd9-0ce46316ed85" complete(0, 0)
2012-05-25 13:03:20,485 DEBUG [Session] ssn:"563f2d63-1c1f-4e45-abd9-0ce46316ed85" commands remaining: 1
2012-05-25 13:03:20,486 DEBUG [Connection] RECV: [conn:6490832e] ch=0 ExecutionResult(commandId=105357, value=QueueQueryResult(queue=quotaTestDestination, du
rable=true, arguments=null, messageCount=4663, subscriberCount=1))
2012-05-25 13:03:20,486 DEBUG [Session] ID: [0] 98
2012-05-25 13:03:20,486 WARN [Session] Received a response to a command that's no longer valid on the client side. [ command id : 105357 , result : QueueQuer
yResult(queue=quotaTestDestination, durable=true, arguments=null, messageCount=4663, subscriberCount=1) ]
2012-05-25 13:03:20,486 DEBUG [Session] ssn:"153d0147-16a9-48c3-8e3c-846d05ab6fc3" processed([98,98]) 97 97
{noformat}
JMS spec does not guaranty thread safety of the session when it is used from different threads (See, JMS specification 1.1, section 2.8 Multithreading). So, it is not a bug but a misusing of the JMS session from different threads.
> AMQP 0-10: AMQSession.getQueueDepth() timed out because of "Received a response to a command that's no longer valid"
> --------------------------------------------------------------------------------------------------------------------
>
> Key: QPID-4018
> URL: https://issues.apache.org/jira/browse/QPID-4018
> Project: Qpid
> Issue Type: Bug
> Components: Java Client
> Affects Versions: 0.16
> Reporter: Alex Rudyy
> Priority: Minor
> Fix For: 0.17
>
> Attachments: client.log, qpid.queue-query-error.log.gz
>
>
> When testing the disk quota functionality added in QPID-3986, our test program failed because AMQSession.getQueueDepth() timed out.
> This problem occured after the test program had been running successfully for about 45 minutes. We have run the same test for many hours using protocol 0-9 without seeing this problem.
> Our client log contained this warning:
> {noformat}
> "Received a response to a command that's no longer valid on the client side . [ command id : 429958, result : QueueQueryDepthResult ..."
> {noformat}
> ... which is presumably the reason for getQueueDepth() timing out.
> The broker log suggests that the queue query command was received, and a response promptly returned to the client.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org