Qpid
  1. Qpid
  2. QPID-3756

ManagedConnectionMBeanTest.testChannels fails on 0-10 spawned profiles

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 0.15
    • Fix Version/s: 0.15
    • Component/s: Java Tests
    • Labels:
      None

      Description

      We see the following test fail occasionally on the java-mms-spawn.0-10 and java-bdb-spawn.0-10. The stack trace is as folows:

      Error Message

      Unexpected number of connection mbeans expected:<0> but was:<1>

      
      Stacktrace
      
      junit.framework.AssertionFailedError: Unexpected number of connection mbeans expected:<0> but was:<1>
      at org.apache.qpid.management.jmx.ManagedConnectionMBeanTest.testChannels(ManagedConnectionMBeanTest.java:125)
      at org.apache.qpid.test.utils.QpidBrokerTestCase.runBare(QpidBrokerTestCase.java:240)
      at org.apache.qpid.test.utils.QpidTestCase.run(QpidTestCase.java:135)
      
      

        Activity

        Hide
        Keith Wall added a comment -

        Problem is that there is a race condition between the broker, closing the connection and unregistering the connection mbean and the test using the mbean to observe the number of connections. When the test fails, the test makes the observation too soon.

        On the 0-10 path, the broker unregisters the mbean (ServerConnection#closed) only after the socket has been closed (IoReceiver.java:175). This is after the broker has sent the ConnectionCloseOk to the client, so the clients #close() call will have already returned control to the caller.

        On 0-8..0-9-1 the unregister is done much earlier (AMQProtocolEngine#closeSession) which is invoked on receipt of ConnectionClose, i.e. before the ConnectionCloseOkBody is sent so the same problem cannot occur.

        We could change 0-10 to unregister the mbean from ServerConnectionDelegate.connectionClose() i.e. before the ConnectionCloseOk is sent to the client. Opinions anyone?

        main 2012-01-13 16:15:27,028 DEBUG [apache.qpid.transport.Connection] SEND: [conn:78dc9766] ch=0 ConnectionClose(replyCode=NORMAL)
        main 2012-01-13 16:15:27,028 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:78dc9766]
        BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,029 DEBUG [apache.qpid.transport.Connection] RECV: [conn:53e6978d] ch=0 ConnectionClose(replyCode=NORMAL)
        BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,029 INFO [qpid.message.connection.close] [con:0(clientid@/127.0.0.1:41093/test)] [con:0(clientid@/127.0.0.1:41093/test)] CON-1002 : Close
        BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,030 DEBUG [apache.qpid.transport.Connection] SEND: [conn:53e6978d] ch=0 ConnectionCloseOk()
        BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,030 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:53e6978d]
        IoReceiver - localhost/127.0.0.1:15672 2012-01-13 16:15:27,030 DEBUG [apache.qpid.transport.Connection] RECV: [conn:78dc9766] ch=0 ConnectionCloseOk()
        IoReceiver - localhost/127.0.0.1:15672 2012-01-13 16:15:27,031 DEBUG [apache.qpid.transport.Connection] connection closed: conn:78dc9766
        XX test close done
        XX getting managed connections
        BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,032 DEBUG [qpid.server.transport.ServerConnection] unregister mbean
        BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,032 DEBUG [apache.qpid.transport.Connection] connection closed: conn:53e6978d
        XX test got managed connections
        
        Show
        Keith Wall added a comment - Problem is that there is a race condition between the broker, closing the connection and unregistering the connection mbean and the test using the mbean to observe the number of connections. When the test fails, the test makes the observation too soon. On the 0-10 path, the broker unregisters the mbean (ServerConnection#closed) only after the socket has been closed (IoReceiver.java:175). This is after the broker has sent the ConnectionCloseOk to the client, so the clients #close() call will have already returned control to the caller. On 0-8..0-9-1 the unregister is done much earlier (AMQProtocolEngine#closeSession) which is invoked on receipt of ConnectionClose, i.e. before the ConnectionCloseOkBody is sent so the same problem cannot occur. We could change 0-10 to unregister the mbean from ServerConnectionDelegate.connectionClose() i.e. before the ConnectionCloseOk is sent to the client. Opinions anyone? main 2012-01-13 16:15:27,028 DEBUG [apache.qpid.transport.Connection] SEND: [conn:78dc9766] ch=0 ConnectionClose(replyCode=NORMAL) main 2012-01-13 16:15:27,028 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:78dc9766] BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,029 DEBUG [apache.qpid.transport.Connection] RECV: [conn:53e6978d] ch=0 ConnectionClose(replyCode=NORMAL) BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,029 INFO [qpid.message.connection.close] [con:0(clientid@/127.0.0.1:41093/test)] [con:0(clientid@/127.0.0.1:41093/test)] CON-1002 : Close BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,030 DEBUG [apache.qpid.transport.Connection] SEND: [conn:53e6978d] ch=0 ConnectionCloseOk() BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,030 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:53e6978d] IoReceiver - localhost/127.0.0.1:15672 2012-01-13 16:15:27,030 DEBUG [apache.qpid.transport.Connection] RECV: [conn:78dc9766] ch=0 ConnectionCloseOk() IoReceiver - localhost/127.0.0.1:15672 2012-01-13 16:15:27,031 DEBUG [apache.qpid.transport.Connection] connection closed: conn:78dc9766 XX test close done XX getting managed connections BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,032 DEBUG [qpid.server.transport.ServerConnection] unregister mbean BROKER: IoReceiver - /127.0.0.1:41093 2012-01-13 16:15:27,032 DEBUG [apache.qpid.transport.Connection] connection closed: conn:53e6978d XX test got managed connections
        Hide
        Keith Wall added a comment -

        Hi Alex, would you mind reviewing this change?

        Show
        Keith Wall added a comment - Hi Alex, would you mind reviewing this change?
        Hide
        Alex Rudyy added a comment -

        The changes seem to be fine for me

        Show
        Alex Rudyy added a comment - The changes seem to be fine for me
        Hide
        Keith Wall added a comment -

        My patch has only reduced the window in which this problem can occur. ConnectionCloseOk is still being sent back to the client before the bean is deregistered, allowing the problem to occur.

        Show
        Keith Wall added a comment - My patch has only reduced the window in which this problem can occur. ConnectionCloseOk is still being sent back to the client before the bean is deregistered, allowing the problem to occur.
        Hide
        Alex Rudyy added a comment -

        Attached a patch containing a fix for the test

        Show
        Alex Rudyy added a comment - Attached a patch containing a fix for the test
        Hide
        Alex Rudyy added a comment -

        Robbie,

        Could you review and commit a patch attached?

        Show
        Alex Rudyy added a comment - Robbie, Could you review and commit a patch attached?
        Hide
        Robbie Gemmell added a comment -

        I dont see this as a test problem, this is a broker side issue.

        As per Keith's original comment, I think we should be unregistering the MBean before responding to the client that the connection is closed, as occurs for 0-9-1 clients. Unregistering the MBean is part of the process of closing, and we should look to prevent the MBean being present and usable for any length of time after the connection is no longer considered live.

        Show
        Robbie Gemmell added a comment - I dont see this as a test problem, this is a broker side issue. As per Keith's original comment, I think we should be unregistering the MBean before responding to the client that the connection is closed, as occurs for 0-9-1 clients. Unregistering the MBean is part of the process of closing, and we should look to prevent the MBean being present and usable for any length of time after the connection is no longer considered live.
        Hide
        Keith Wall added a comment -

        I've attached a patch to ConnectionDelegate.java to resolve this problem.

        It works by reordering the ConnectionCloseOk response so that it occurs after the internal state is updated. Obviously this change will affect both client and broker. I did consider making the change Broker side only by overriding the method within ServerConnectionDelegate.java, but this would only serve to introduce more complexity and difference between broker/client. Robbie/Alex, what do you both think?

        Show
        Keith Wall added a comment - I've attached a patch to ConnectionDelegate.java to resolve this problem. It works by reordering the ConnectionCloseOk response so that it occurs after the internal state is updated. Obviously this change will affect both client and broker. I did consider making the change Broker side only by overriding the method within ServerConnectionDelegate.java, but this would only serve to introduce more complexity and difference between broker/client. Robbie/Alex, what do you both think?
        Hide
        Robbie Gemmell added a comment -

        I think I might actually lean toward confining the change in behaviour to the broker. I recall doing that exact change when Alex and I were looking at the failover stuff last year, and we ended up reverting it. I cant remember what the precise reason but I think the change had unexpected failover related side effects on the client. The method already is overriden in ServerConnectionDelegate, albeit currently it subsequently calls the superclass implementation.

        Show
        Robbie Gemmell added a comment - I think I might actually lean toward confining the change in behaviour to the broker. I recall doing that exact change when Alex and I were looking at the failover stuff last year, and we ended up reverting it. I cant remember what the precise reason but I think the change had unexpected failover related side effects on the client. The method already is overriden in ServerConnectionDelegate, albeit currently it subsequently calls the superclass implementation.
        Hide
        Keith Wall added a comment -

        I've committed a patch to change the Broker side behaviour as agreed above.
        Robbie, could you re-review please?

        Show
        Keith Wall added a comment - I've committed a patch to change the Broker side behaviour as agreed above. Robbie, could you re-review please?
        Hide
        Robbie Gemmell added a comment -

        Looks ok to me.

        Show
        Robbie Gemmell added a comment - Looks ok to me.

          People

          • Assignee:
            Keith Wall
            Reporter:
            Keith Wall
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development