[QPID-7259] qpid_tests.broker_0_10.message.MessageTests.test_window_flow_messages occasionally fails against the Java Broker - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Closed
Priority: Minor
Resolution: Fixed
Affects Version/s: None
Fix Version/s: qpid-python-1.35.0
Component/s: Python Test Suite
Labels:
None
Environment:

Darwin Oslo.local 15.4.0 Darwin Kernel Version 15.4.0: Fri Feb 26 22:08:05 PST 2016; root:xnu-3248.40.184~3/RELEASE_X86_64 x86_64
Python 2.7.10
Qpid Python Client (trunk) - not swigged
Java Broker (trunk)

Description

Running qpid_tests.broker_0_10.message.MessageTests.test_window_flow_messages (Pure python - unswigged) against the Java Broker (trunk), I occasionally see the following failure:

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

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:

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)

A passing case:

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)

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending

fail.log
12/May/16 06:03
40 kB
Keith Wall
success.log
12/May/16 06:02
40 kB
Keith Wall

Activity

People

Assignee:: Unassigned

Reporter:: Keith Wall

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 12/May/16 05:56

Updated:: 06/Sep/16 20:43

Resolved:: 12/May/16 12:44