[
https://issues.apache.org/jira/browse/QPID-7259?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15281234#comment-15281234
]
Keith Wall edited comment on QPID-7259 at 5/12/16 6:03 AM:
-----------------------------------------------------------
It appears the test tries to control the completions manually, but there is a
TODO left in the test code (Line 487), but it appears that something else
(messaging itself??) is doing the completions too.
Attached two file contain Broker log for successful and failing case.
was (Author: k-wall):
It appears the test tries to control the completions manually, but there is a
TODO left in the test code (Line 487), but it appears that something else
(messaging itself??) is doing the completions too.
> 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
> Priority: Minor
> Attachments: fail.log, success.log
>
>
> 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]
