Keith Wall created QPID-7259:
--------------------------------
Summary:
qpid_tests.broker_0_10.message.MessageTests.test_window_flow_messages
occasionally fails against the Java Broker
Key: QPID-7259
URL: https://issues.apache.org/jira/browse/QPID-7259
Project: Qpid
Issue Type: Bug
Components: Python Test Suite
Reporter: Keith Wall
Running
{{qpid_tests.broker_0_10.message.MessageTests.test_window_flow_messages}}
against the Java Broker (trunk), I occasionally see the following failure:
{noformat}
qpid_tests.broker_0_10.message.MessageTests.test_window_flow_messages
...........................................................................................................................................................................
fail
Error during test: Traceback (most recent call last):
File "/Users/keith/py/bin/qpid-python-test", line 340, in run
phase()
File
"/Users/keith/py/lib/python2.7/site-packages/qpid_tests/broker_0_10/message.py",
line 489, in test_window_flow_messages
self.assertEmpty(q)
File
"/Users/keith/py/lib/python2.7/site-packages/qpid_tests/broker_0_10/message.py",
line 1109, in assertEmpty
self.fail("Queue not empty, contains: " + extra.body)
File
"/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/unittest/case.py",
line 412, in fail
raise self.failureException(msg)
AssertionError: Queue not empty, contains: Message 6
{noformat}
Turning debug on, you can see on the failing case, the client side emits an
additional SessionCompleted(commands=[0, 0]), allowing the Broker to
legitimately send message 6. In the passing case the
SessionCompleted(commands=null) is sent instead.
The failing case:
{noformat}
016-05-11 23:16:16,341 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection) -
RECV: [conn:6be9e091] ch=1 [S] MessageFlow(destination=c, unit=MESSAGE, value=5)
2016-05-11 23:16:16,341 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Session) -
identify: ch=1, commandId=13
2016-05-11 23:16:16,341 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Session) -
ssn:"test-session" ch=1 processed([13,13]) 12 12
2016-05-11 23:16:16,341 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Session) -
ssn:"test-session" processed: {[0, 12]}
2016-05-11 23:16:16,341 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- SEND: [conn:6be9e091] ch=1 SessionCompleted(commands={[0, 13]})
2016-05-11 23:16:16,341 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- FLUSH: [conn:6be9e091]
2016-05-11 23:16:16,341 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Written 26 bytes
2016-05-11 23:16:16,341 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
2016-05-11 23:16:16,342 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Read 25 byte(s)
2016-05-11 23:16:16,342 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- RECV: [conn:6be9e091] ch=1 [S] MessageFlow(destination=c, unit=BYTE,
value=4294967295)
2016-05-11 23:16:16,342 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Session) -
identify: ch=1, commandId=14
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Session) -
ssn:"test-session" ch=1 processed([14,14]) 13 13
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Session) -
ssn:"test-session" processed: {[0, 13]}
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- SEND: [conn:6be9e091] ch=1 SessionCompleted(commands={[0, 14]})
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- FLUSH: [conn:6be9e091]
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Written 26 bytes
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- SEND: [conn:6be9e091] ch=1 SessionCommandPoint(commandId=0, commandOffset=0)
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- FLUSH: [conn:6be9e091]
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- SEND: [conn:6be9e091] ch=1 id=0 [B] MessageTransfer(destination=c,
acceptMode=EXPLICIT, acquireMode=PRE_ACQUIRED)
DeliveryProperties(routingKey=q)
body="Message 1"
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- SEND: [conn:6be9e091] ch=1 SessionFlush(completed=true)
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- FLUSH: [conn:6be9e091]
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- SEND: [conn:6be9e091] ch=1 id=1 [B] MessageTransfer(destination=c,
acceptMode=EXPLICIT, acquireMode=PRE_ACQUIRED)
DeliveryProperties(routingKey=q)
body="Message 2"
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- SEND: [conn:6be9e091] ch=1 id=2 [B] MessageTransfer(destination=c,
acceptMode=EXPLICIT, acquireMode=PRE_ACQUIRED)
DeliveryProperties(routingKey=q)
body="Message 3"
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- SEND: [conn:6be9e091] ch=1 id=3 [B] MessageTransfer(destination=c,
acceptMode=EXPLICIT, acquireMode=PRE_ACQUIRED)
DeliveryProperties(routingKey=q)
body="Message 4"
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- SEND: [conn:6be9e091] ch=1 id=4 [B] MessageTransfer(destination=c,
acceptMode=EXPLICIT, acquireMode=PRE_ACQUIRED)
DeliveryProperties(routingKey=q)
body="Message 5"
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
2016-05-11 23:16:16,343 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Written 369 bytes
2016-05-11 23:16:16,345 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Read 26 byte(s)
2016-05-11 23:16:16,345 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- RECV: [conn:6be9e091] ch=1 SessionCompleted(commands=[0, 0])
2016-05-11 23:16:16,345 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Session) -
ssn:"test-session" complete(0, 0)
2016-05-11 23:16:16,345 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Session) -
ssn:"test-session" commands remaining: 5
2016-05-11 23:16:16,345 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
2016-05-11 23:16:16,345 DEBUG [IO-/0:0:0:0:0:0:0:1:54458] (o.a.q.t.Connection)
- SEND: [conn:6be9e091] ch=1 id=5 [B] MessageTransfer(destination=c,
acceptMode=EXPLICIT, acquireMode=PRE_ACQUIRED)
DeliveryProperties(routingKey=q)
body="Message 6"
2016-05-11 23:16:16,345 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
2016-05-11 23:16:16,345 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Written 65 bytes
2016-05-11 23:16:16,346 DEBUG [IO-/0:0:0:0:0:0:0:1:54458]
(o.a.q.s.t.NonBlockingConnection) - Read 30 byte(s)
{noformat}
A passing case:
{noformat}
2016-05-11 23:16:13,660 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- RECV: [conn:287b2153] ch=1 [S] MessageFlow(destination=c, unit=BYTE,
value=4294967295)
2016-05-11 23:16:13,660 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Session) -
identify: ch=1, commandId=14
2016-05-11 23:16:13,660 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Session) -
ssn:"test-session" ch=1 processed([14,14]) 13 13
2016-05-11 23:16:13,660 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Session) -
ssn:"test-session" processed: {[0, 13]}
2016-05-11 23:16:13,660 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- SEND: [conn:287b2153] ch=1 SessionCompleted(commands={[0, 14]})
2016-05-11 23:16:13,660 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- FLUSH: [conn:287b2153]
2016-05-11 23:16:13,660 DEBUG [IO-/0:0:0:0:0:0:0:1:54457]
(o.a.q.s.t.NonBlockingConnection) - Written 26 bytes
2016-05-11 23:16:13,660 DEBUG [IO-/0:0:0:0:0:0:0:1:54457]
(o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
2016-05-11 23:16:13,660 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- SEND: [conn:287b2153] ch=1 SessionCommandPoint(commandId=0, commandOffset=0)
2016-05-11 23:16:13,660 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- FLUSH: [conn:287b2153]
2016-05-11 23:16:13,660 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- SEND: [conn:287b2153] ch=1 id=0 [B] MessageTransfer(destination=c,
acceptMode=EXPLICIT, acquireMode=PRE_ACQUIRED)
DeliveryProperties(routingKey=q)
body="Message 1"
2016-05-11 23:16:13,661 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- SEND: [conn:287b2153] ch=1 SessionFlush(completed=true)
2016-05-11 23:16:13,661 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- FLUSH: [conn:287b2153]
2016-05-11 23:16:13,661 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- SEND: [conn:287b2153] ch=1 id=1 [B] MessageTransfer(destination=c,
acceptMode=EXPLICIT, acquireMode=PRE_ACQUIRED)
DeliveryProperties(routingKey=q)
body="Message 2"
2016-05-11 23:16:13,661 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- SEND: [conn:287b2153] ch=1 id=2 [B] MessageTransfer(destination=c,
acceptMode=EXPLICIT, acquireMode=PRE_ACQUIRED)
DeliveryProperties(routingKey=q)
body="Message 3"
2016-05-11 23:16:13,661 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- SEND: [conn:287b2153] ch=1 id=3 [B] MessageTransfer(destination=c,
acceptMode=EXPLICIT, acquireMode=PRE_ACQUIRED)
DeliveryProperties(routingKey=q)
body="Message 4"
2016-05-11 23:16:13,661 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- SEND: [conn:287b2153] ch=1 id=4 [B] MessageTransfer(destination=c,
acceptMode=EXPLICIT, acquireMode=PRE_ACQUIRED)
DeliveryProperties(routingKey=q)
body="Message 5"
2016-05-11 23:16:13,661 DEBUG [IO-/0:0:0:0:0:0:0:1:54457]
(o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
2016-05-11 23:16:13,661 DEBUG [IO-/0:0:0:0:0:0:0:1:54457]
(o.a.q.s.t.NonBlockingConnection) - Written 369 bytes
2016-05-11 23:16:13,661 DEBUG [IO-/0:0:0:0:0:0:0:1:54457]
(o.a.q.s.t.NonBlockingConnection) - Read 18 byte(s)
2016-05-11 23:16:13,661 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- RECV: [conn:287b2153] ch=1 SessionCompleted(commands=null)
2016-05-11 23:16:13,661 DEBUG [IO-/0:0:0:0:0:0:0:1:54457]
(o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
2016-05-11 23:16:14,664 DEBUG [IO-/0:0:0:0:0:0:0:1:54457]
(o.a.q.s.t.NonBlockingConnection) - Read 26 byte(s)
2016-05-11 23:16:14,664 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Connection)
- RECV: [conn:287b2153] ch=1 SessionCompleted(commands=[0, 4])
2016-05-11 23:16:14,664 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Session) -
ssn:"test-session" complete(0, 4)
2016-05-11 23:16:14,664 DEBUG [IO-/0:0:0:0:0:0:0:1:54457] (o.a.q.t.Session) -
ssn:"test-session" commands remaining: 1
2016-05-11 23:16:14,664 DEBUG [IO-/0:0:0:0:0:0:0:1:54457]
(o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
