Uploaded image for project: 'Qpid'
  1. Qpid
  2. QPID-7259

qpid_tests.broker_0_10.message.MessageTests.test_window_flow_messages occasionally fails against the Java Broker

    XMLWordPrintableJSON

    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

        1. fail.log
          40 kB
          Keith Wall
        2. success.log
          40 kB
          Keith Wall

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              k-wall Keith Wall
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: