Qpid
  1. Qpid
  2. QPID-4052

HAClusterTwoNodeTest.testSecondaryDesignatedAsPrimaryAfterOrginalPrimaryStopped occasionally fails on Apache CI

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 0.17
    • Fix Version/s: 0.17
    • Component/s: Java Broker, Java Tests
    • Labels:
      None

      Description

      New HA test is showing occasionally failures on Apache CI e.g. builds 297 and 298.

      https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Java-Java-BDB-TestMatrix/297/jdk=JDK%201.6%20%28latest%29,label=Ubuntu,profile=java-bdb.0-10/testReport/junit/org.apache.qpid.server.store.berkeleydb/HAClusterTwoNodeTest/testSecondaryDesignatedAsPrimaryAfterOrginalPrimaryStopped/

      https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Java-Java-BDB-TestMatrix/298/jdk=JDK%201.6%20%28latest%29,label=Ubuntu,profile=java-bdb.0-10/testReport/org.apache.qpid.server.store.berkeleydb/HAClusterTwoNodeTest/testSecondaryDesignatedAsPrimaryAfterOrginalPrimaryStopped/

      javax.jms.JMSException: Error creating connection: Connection refused
      	at org.apache.qpid.client.AMQConnectionFactory.createConnection(AMQConnectionFactory.java:159)
      	at org.apache.qpid.client.AMQConnectionFactory.createConnection(AMQConnectionFactory.java:134)
      	at org.apache.qpid.test.utils.QpidBrokerTestCase.getConnection(QpidBrokerTestCase.java:1038)
      	at org.apache.qpid.server.store.berkeleydb.HAClusterTwoNodeTest.testSecondaryDesignatedAsPrimaryAfterOrginalPrimaryStopped(HAClusterTwoNodeTest.java:189)
      	at org.apache.qpid.test.utils.QpidBrokerTestCase.runBare(QpidBrokerTestCase.java:237)
      	at org.apache.qpid.test.utils.QpidTestCase.run(QpidTestCase.java:139)
      Caused by: org.apache.qpid.AMQConnectionFailureException: Connection refused
      	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:444)
      	at org.apache.qpid.client.AMQConnectionFactory.createConnection(AMQConnectionFactory.java:155)
      Caused by: org.apache.qpid.transport.TransportException: Error connecting to broker
      	at org.apache.qpid.transport.network.io.IoNetworkTransport.connect(IoNetworkTransport.java:82)
      	at org.apache.qpid.transport.Connection.connect(Connection.java:235)
      	at org.apache.qpid.client.AMQConnectionDelegate_0_10.makeBrokerConnection(AMQConnectionDelegate_0_10.java:219)
      	at org.apache.qpid.client.AMQConnection.makeBrokerConnection(AMQConnection.java:588)
      	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:367)
      Caused by: java.net.ConnectException: Connection refused
      	at java.net.PlainSocketImpl.socketConnect(Native Method)
      	at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
      	at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
      	at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
      	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
      	at java.net.Socket.connect(Socket.java:529)
      	at org.apache.qpid.transport.network.io.IoNetworkTransport.connect(IoNetworkTransport.java:78)
      

        Activity

        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open In Progress In Progress
        1d 14h 35m 1 Keith Wall 12/Jun/12 22:58
        In Progress In Progress Reviewable Reviewable
        2d 16h 3m 1 Keith Wall 15/Jun/12 15:02
        Reviewable Reviewable Resolved Resolved
        58d 5h 47m 1 Robbie Gemmell 12/Aug/12 20:50
        Resolved Resolved Closed Closed
        913d 16m 1 Rob Godfrey 11/Feb/15 20:06
        Rob Godfrey made changes -
        Status Resolved [ 5 ] Closed [ 6 ]
        Rob Godfrey made changes -
        Component/s Java Broker [ 12311388 ]
        Component/s Java Broker BDB Store [ 12315809 ]
        Robbie Gemmell made changes -
        Status Ready To Review [ 10006 ] Resolved [ 5 ]
        Resolution Fixed [ 1 ]
        Hide
        Robbie Gemmell added a comment -

        Resolving.

        Show
        Robbie Gemmell added a comment - Resolving.
        Keith Wall made changes -
        Assignee Keith Wall [ k-wall ] Philip Harvey [ philharveyonline ]
        Hide
        Keith Wall added a comment -

        Patch applied.

        Show
        Keith Wall added a comment - Patch applied.
        Keith Wall made changes -
        Status In Progress [ 3 ] Ready To Review [ 10006 ]
        Hide
        Keith Wall added a comment -

        This is a timing issue within the test. From the logs you are see that the client burns all its chances to connect before the node has designated primary has been made master.

        Here are the pertinent parts of the log showing the designation as primary, the client's attempts to connect, followed by the primary becoming master.
        Notice that the client burns most of its attempts to connect before the primary becomes master.

        Giving the client more chances to connect will resolve this issue.

        BROKER: RMI TCP Connection(2)-67.195.138.60 2012-06-12 17:04:02,638 INFO [server.store.berkeleydb.BDBHAMessageStore] Node nodetestSecondaryDesignatedAsPrimaryAfterOrginalPrimaryStopped10003 successfully set as designated primary for group
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:02,640 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:02,641 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:03,750 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:03,764 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:03,764 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:03,765 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:04,777 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:04,789 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:04,790 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:04,790 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:05,801 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:05,813 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:05,814 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:05,815 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:06,826 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:06,848 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:06,849 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:06,849 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:07,861 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ********
        BROKER: UNKNOWN nodetestSecondaryDesignatedAsPrimaryAfterOrginalPrimaryStopped10003(2) 2012-06-12 17:04:08,411 INFO [server.store.berkeleydb.BDBHAMessageStore] Received BDB event indicating transition to state MASTER
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:08,415 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:08,416 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        
        Show
        Keith Wall added a comment - This is a timing issue within the test. From the logs you are see that the client burns all its chances to connect before the node has designated primary has been made master. Here are the pertinent parts of the log showing the designation as primary, the client's attempts to connect, followed by the primary becoming master. Notice that the client burns most of its attempts to connect before the primary becomes master. Giving the client more chances to connect will resolve this issue. BROKER: RMI TCP Connection(2)-67.195.138.60 2012-06-12 17:04:02,638 INFO [server.store.berkeleydb.BDBHAMessageStore] Node nodetestSecondaryDesignatedAsPrimaryAfterOrginalPrimaryStopped10003 successfully set as designated primary for group MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:02,640 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:02,641 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:03,750 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:03,764 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:03,764 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:03,765 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:04,777 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:04,789 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:04,790 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:04,790 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:05,801 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:05,813 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:05,814 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:05,815 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:06,826 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:06,848 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:06,849 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:06,849 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:07,861 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10002 vhost: test username: guest password: ******** BROKER: UNKNOWN nodetestSecondaryDesignatedAsPrimaryAfterOrginalPrimaryStopped10003(2) 2012-06-12 17:04:08,411 INFO [server.store.berkeleydb.BDBHAMessageStore] Received BDB event indicating transition to state MASTER MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:08,415 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ******** MASTER nodetestSetSystemConfiguration10000(1) 2012-06-12 17:04:08,416 DEBUG [apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost port: 10000 vhost: test username: guest password: ********
        Keith Wall made changes -
        Field Original Value New Value
        Status Open [ 1 ] In Progress [ 3 ]
        Keith Wall created issue -

          People

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

            Dates

            • Created:
              Updated:
              Resolved:

              Development