qpid-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Alex Rudyy (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (QPID-4018) AMQP 0-10: AMQSession.getQueueDepth() timed out because of "Received a response to a command that's no longer valid"
Date Fri, 25 May 2012 13:50:23 GMT

    [ 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.

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,
2012-05-25 13:03:20,459 DEBUG [BasicMessageProducer_0_10] MessageProducer org.apache.qpid.client.BasicMessageProducer_0_10@44da44a6
using publish mode : ASYN
2012-05-25 13:03:20,460 DEBUG [Connection] RECV: [conn:6490832e] ch=1 MessageSetFlowMode(destination=,
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,
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
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
  DeliveryProperties(priority=MEDIUM, deliveryMode=PERSISTENT, timestamp=1337947400319, exchange=amq.direct,
  MessageProperties(contentLength=10000, messageId=ddea0af9-520c-314b-87a3-24ff1da9e4ef, contentType=text/plain,
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,
2012-05-25 13:03:20,461 DEBUG [Session] ssn:"153d0147-16a9-48c3-8e3c-846d05ab6fc3" complete(105213,
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,
2012-05-25 13:03:20,485 DEBUG [Session] ssn:"563f2d63-1c1f-4e45-abd9-0ce46316ed85" complete(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


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

View raw message