You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Keith Wall (JIRA)" <ji...@apache.org> on 2012/07/22 12:37:33 UTC
[jira] [Updated] (QPID-4162)
AlternateExchangeTests.test_queue_autodelete occasionally fails with
ProtocolViolationException on Java Broker
[ https://issues.apache.org/jira/browse/QPID-4162?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Keith Wall updated QPID-4162:
-----------------------------
Description:
As exemplified by builds [build 279|https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Python-Java-Test/279/] and [build 284|https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Python-Java-Test/284/], test qpid_tests.broker_0_10.alternate_exchange.AlternateExchangeTests.test_queue_autodelete is occasionally seen to fail against only the Java Broker.
{noformat}
Error during test: Traceback (most recent call last):
File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/python/qpid-python-test", line 340, in run
phase()
File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/tests/src/py/qpid_tests/broker_0_10/alternate_exchange.py", line 231, in test_queue_autodelete
self.assertEmpty(dlq)
File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/tests/src/py/qpid_tests/broker_0_10/alternate_exchange.py", line 351, in assertEmpty
msg = queue.get(timeout=1)
File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/python/qpid/queue.py", line 55, in get
raise Closed(self.error)
Closed: (None, 'connection aborted')
{noformat}
was:
As exemplified by builds [build 279|builds https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Python-Java-Test/279/] and [build 284|builds https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Python-Java-Test/284/], test qpid_tests.broker_0_10.alternate_exchange.AlternateExchangeTests.test_queue_autodelete is occasionally seen to fail against only the Java Broker.
{noformat}
Error during test: Traceback (most recent call last):
File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/python/qpid-python-test", line 340, in run
phase()
File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/tests/src/py/qpid_tests/broker_0_10/alternate_exchange.py", line 231, in test_queue_autodelete
self.assertEmpty(dlq)
File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/tests/src/py/qpid_tests/broker_0_10/alternate_exchange.py", line 351, in assertEmpty
msg = queue.get(timeout=1)
File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/python/qpid/queue.py", line 55, in get
raise Closed(self.error)
Closed: (None, 'connection aborted')
{noformat}
*Background*
Test fails with an assert failure at line 231:
{code:title=alternate_exchange.py}
self.assertEqual("Three", dlq.get(timeout=2).body)
{code}
the test tries to check for the presence of message Three, but finds the queue has already been marked as closed (on the client side by Session#close). The queue is being marked as closed in the response to the Broker closing the socket *abruptly*. The Broker is closing the socket owning to a ProtocolViolationException.
{noformat}
2012-07-21 00:40:06,070 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - connection closed: conn:1a9d267d
{noformat}
Exception (not logged):
{noformat}
org.apache.qpid.transport.ProtocolViolationException: Received frames for an already detached session
at org.apache.qpid.transport.Connection.dispatch(Connection.java:445)
at org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:64)
at org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:40)
at org.apache.qpid.transport.MethodDelegate.sessionCompleted(MethodDelegate.java:92)
at org.apache.qpid.transport.SessionCompleted.dispatch(SessionCompleted.java:88)
at org.apache.qpid.transport.ConnectionDelegate.control(ConnectionDelegate.java:49)
at org.apache.qpid.transport.ConnectionDelegate.control(ConnectionDelegate.java:40)
at org.apache.qpid.transport.Method.delegate(Method.java:163)
at org.apache.qpid.transport.Connection.received(Connection.java:379)
at org.apache.qpid.server.transport.ServerConnection.received(ServerConnection.java:212)
at org.apache.qpid.server.transport.ServerConnection.received(ServerConnection.java:56)
at org.apache.qpid.transport.network.Assembler.emit(Assembler.java:97)
at org.apache.qpid.transport.network.Assembler.assemble(Assembler.java:183)
{noformat}
*Cause*
Broker generates the ProtocolViolationException in response to a SessionCompleted command received from the client *after* it has already processed the SessionDetach.
The reason the sporadic nature of the test failure is due to a race.
The Broker sends a SessionFlush at approximately the same time the client is closing the session (session2.close() line 225). If the client responds to the flush before it sends its SessionDetach all is well. However, if the client sends its SessionDetach first, then its subsequent SessionCompleted reply will cause the PVE on the Broker.
Here's a grep from the Broker's log during a failing case:
{noformat}
2012-07-21 00:40:06,020 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 0]})
2012-07-21 00:40:06,029 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 1]})
2012-07-21 00:40:06,039 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 2]})
2012-07-21 00:40:06,043 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 3]})
2012-07-21 00:40:06,046 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 4]})
2012-07-21 00:40:06,049 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 5]})
2012-07-21 00:40:06,050 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 6]})
2012-07-21 00:40:06,054 DEBUG [pool-3-thread-7] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionFlush(completed=true)
2012-07-21 00:40:06,056 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - RECV: [conn:1a9d267d] ch=2 SessionDetach(name=[B@21144823)
2012-07-21 00:40:06,057 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionDetached(name=[B@21144823, code=NORMAL)
2012-07-21 00:40:06,070 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - RECV: [conn:1a9d267d] ch=2 SessionCompleted(commands=null) #!!1
2012-07-21 00:40:06,070 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - connection closed: conn:1a9d267d #!!2
{noformat}
#!!1 SessionCompleted received after session detach
#!!2 Broker closing connection
> AlternateExchangeTests.test_queue_autodelete occasionally fails with ProtocolViolationException on Java Broker
> --------------------------------------------------------------------------------------------------------------
>
> Key: QPID-4162
> URL: https://issues.apache.org/jira/browse/QPID-4162
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker, Python Test Suite
> Affects Versions: 0.16, 0.17
> Environment: Ubuntu (Apache CI slaves) and Mac OS X 10.6.8
> Reporter: Keith Wall
> Assignee: Keith Wall
>
> As exemplified by builds [build 279|https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Python-Java-Test/279/] and [build 284|https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Python-Java-Test/284/], test qpid_tests.broker_0_10.alternate_exchange.AlternateExchangeTests.test_queue_autodelete is occasionally seen to fail against only the Java Broker.
> {noformat}
> Error during test: Traceback (most recent call last):
> File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/python/qpid-python-test", line 340, in run
> phase()
> File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/tests/src/py/qpid_tests/broker_0_10/alternate_exchange.py", line 231, in test_queue_autodelete
> self.assertEmpty(dlq)
> File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/tests/src/py/qpid_tests/broker_0_10/alternate_exchange.py", line 351, in assertEmpty
> msg = queue.get(timeout=1)
> File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/python/qpid/queue.py", line 55, in get
> raise Closed(self.error)
> Closed: (None, 'connection aborted')
> {noformat}
--
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