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

[Java Broker]Test BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached fails sporadically

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 0.30
    • Component/s: Broker-J
    • Labels:
      None

      Description

      org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached
      Failing for the past 1 build (Since Failed#167 )
      Took 16 sec.
      Error Message

      eventLogger.message(
      <Capturing argument>,
      <Capturing argument>
      );
      Wanted 2 times:
      -> at org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached(BDBHAVirtualHostNodeOperationalLoggingTest.java:369)
      But was 1 time:
      -> at org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer.onNodeState(BDBHAVirtualHostNodeImpl.java:799)

      Stacktrace

      org.mockito.exceptions.verification.TooLittleActualInvocations: 
      eventLogger.message(
          <Capturing argument>,
          <Capturing argument>
      );
      Wanted 2 times:
      -> at org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached(BDBHAVirtualHostNodeOperationalLoggingTest.java:369)
      But was 1 time:
      -> at org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer.onNodeState(BDBHAVirtualHostNodeImpl.java:799)
      
      	at org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached(BDBHAVirtualHostNodeOperationalLoggingTest.java:369)
      

      Standard Output

      main 2014-08-11 14:14:33,876 INFO [qpid.test.utils.QpidTestCase] ========== start BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached ==========
      main 2014-08-11 14:14:33,879 DEBUG [qpid.server.plugin.QpidServiceLoader] Found 42 implementations of interface org.apache.qpid.server.plugin.ConfiguredObjectTypeFactory
      main 2014-08-11 14:14:33,882 DEBUG [server.configuration.updater.TaskExecutorImpl] Starting task executor
      main 2014-08-11 14:14:33,883 DEBUG [server.configuration.updater.TaskExecutorImpl] Task executor is started
      main 2014-08-11 14:14:33,899 DEBUG [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Activating virtualhost node BDBHAVirtualHostNodeImpl [id=1af44e76-4cb2-43bb-83d7-053586beb749, name=node1, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node1, groupName=group, address=localhost:10000, state=UNINITIALIZED, priority=1, designatedPrimary=true, quorumOverride=0]
      main 2014-08-11 14:14:33,899 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Creating environment
      main 2014-08-11 14:14:33,899 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment path /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node1
      main 2014-08-11 14:14:33,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Group name group
      main 2014-08-11 14:14:33,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node name node1
      main 2014-08-11 14:14:33,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node host port localhost:10000
      main 2014-08-11 14:14:33,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper host port localhost:10000
      main 2014-08-11 14:14:33,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper node name node1
      main 2014-08-11 14:14:33,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Durability SYNC,NO_SYNC,SIMPLE_MAJORITY
      main 2014-08-11 14:14:33,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Designated primary (applicable to 2 node case only) true
      main 2014-08-11 14:14:33,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node priority 1
      main 2014-08-11 14:14:33,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Quorum override 0
      main 2014-08-11 14:14:33,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Permitted node list []
      main 2014-08-11 14:14:33,902 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.repStreamTimeout to '1 h'
      main 2014-08-11 14:14:33,902 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.protocolOldStringEncoding to 'false'
      main 2014-08-11 14:14:33,902 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.logFlushTaskInterval to '1 min'
      main 2014-08-11 14:14:33,902 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envSetupTimeout to '15 min'
      main 2014-08-11 14:14:33,903 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envUnknownStateTimeout to '5 s'
      main 2014-08-11 14:14:33,903 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.replicaAckTimeout to '2 s'
      main 2014-08-11 14:14:33,903 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.insufficientReplicasTimeout to '2 s'
      main 2014-08-11 14:14:33,904 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.stats.collect to 'false'
      main 2014-08-11 14:14:33,904 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.lock.nLockTables to '7'
      MASTER node1(1) 2014-08-11 14:14:33,967 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment is created for node group:node1
      main 2014-08-11 14:14:33,968 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node1' state is MASTER
      Group-Change-Learner:group:node1 2014-08-11 14:14:33,969 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Received BDB event, new BDB state MASTER Facade state : OPENING
      Group-Change-Learner:group:node1 2014-08-11 14:14:33,969 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The environment facade is in open state for node group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:33,969 INFO [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Received BDB event indicating transition to state MASTER
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,457 DEBUG [store.berkeleydb.upgrade.Upgrader] Source message store version is 8
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,457 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,501 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS new handle
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,502 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,503 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,922 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY new handle
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,922 INFO [qpid.server.store.GenericStoreUpgrader] VirtualHost store has model version 2.0. Number of record(s) 0
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,922 DEBUG [qpid.server.store.GenericStoreUpgrader] VirtualHost store upgrade is about to complete. 0 total record(s). Records to update 0 Records to delete 0
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,923 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@438312ce
      Broker-Configuration-Thread 2014-08-11 14:14:34,924 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@438312ce
      Broker-Configuration-Thread 2014-08-11 14:14:34,924 DEBUG [qpid.server.store.GenericRecoverer] Recovering the children of BDBHAVirtualHostNodeImpl [id=1af44e76-4cb2-43bb-83d7-053586beb749, name=node1, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node1, groupName=group, address=localhost:10000, state=ACTIVE, priority=1, designatedPrimary=true, quorumOverride=0]
      Broker-Configuration-Thread 2014-08-11 14:14:34,924 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@438312ce is performed successfully with result:null
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,925 DEBUG [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Creating new virtualhost with name : group
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,929 DEBUG [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Using virtualhost blueprint {permittedNodes=[localhost:10000, localhost:10001], type=BDB_HA}
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,930 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$10@64066696
      Broker-Configuration-Thread 2014-08-11 14:14:34,930 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$10@64066696
      Broker-Configuration-Thread 2014-08-11 14:14:34,932 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-delivered-group-33
      Broker-Configuration-Thread 2014-08-11 14:14:34,932 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-delivered-group-34
      Broker-Configuration-Thread 2014-08-11 14:14:34,932 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-received-group-35
      Broker-Configuration-Thread 2014-08-11 14:14:34,932 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-received-group-36
      Broker-Configuration-Thread 2014-08-11 14:14:34,935 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting permitted nodes to [localhost:10000, localhost:10001]
      Group-Change-Learner:group:node1 2014-08-11 14:14:34,970 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Broker-Configuration-Thread 2014-08-11 14:14:35,193 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Create ConfiguredObjectRecord [id=b125a36b-8e28-417d-9d96-9b5b35344b51, type=VirtualHost, attributes={createdBy=null, lastUpdatedTime=1407780874932, createdTime=1407780874932, permittedNodes=[localhost:10000, localhost:10001], lastUpdatedBy=null, name=group, modelVersion=2.0, type=BDB_HA}]
      Broker-Configuration-Thread 2014-08-11 14:14:35,194 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Storing configured object record: ConfiguredObjectRecord [id=b125a36b-8e28-417d-9d96-9b5b35344b51, type=VirtualHost, attributes={createdBy=null, lastUpdatedTime=1407780874932, createdTime=1407780874932, permittedNodes=[localhost:10000, localhost:10001], lastUpdatedBy=null, name=group, modelVersion=2.0, type=BDB_HA}]
      Broker-Configuration-Thread 2014-08-11 14:14:35,197 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:35,333 DEBUG [qpid.server.plugin.QpidServiceLoader] Found 0 implementations of interface org.apache.qpid.server.plugin.SystemNodeCreator
      Broker-Configuration-Thread 2014-08-11 14:14:35,338 DEBUG [store.berkeleydb.upgrade.Upgrader] Source message store version is 8
      Broker-Configuration-Thread 2014-08-11 14:14:35,339 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:35,342 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:35,347 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Create [name=amq.direct, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=9e3882b1-5a59-3b39-9892-c5ee0e733528]
      Broker-Configuration-Thread 2014-08-11 14:14:35,348 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Storing configured object record: [name=amq.direct, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=9e3882b1-5a59-3b39-9892-c5ee0e733528]
      Broker-Configuration-Thread 2014-08-11 14:14:35,351 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:35,352 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:35,369 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Create [name=amq.topic, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=13befa16-0b6d-35ef-8d42-e2cae8038115]
      Broker-Configuration-Thread 2014-08-11 14:14:35,369 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Storing configured object record: [name=amq.topic, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=13befa16-0b6d-35ef-8d42-e2cae8038115]
      Broker-Configuration-Thread 2014-08-11 14:14:35,479 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:35,480 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:35,720 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Create [name=amq.match, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=dfe1947f-8661-3342-8d44-d9f00e2ca410]
      Broker-Configuration-Thread 2014-08-11 14:14:35,720 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Storing configured object record: [name=amq.match, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=dfe1947f-8661-3342-8d44-d9f00e2ca410]
      Broker-Configuration-Thread 2014-08-11 14:14:35,787 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:35,788 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:35,819 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Create [name=amq.fanout, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=9547f9e9-94c5-3e90-bcee-a0aef0399240]
      Broker-Configuration-Thread 2014-08-11 14:14:35,820 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Storing configured object record: [name=amq.fanout, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=9547f9e9-94c5-3e90-bcee-a0aef0399240]
      Broker-Configuration-Thread 2014-08-11 14:14:35,823 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:35,824 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:35,972 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Broker-Configuration-Thread 2014-08-11 14:14:36,243 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase MESSAGE_METADATA for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:36,248 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase MESSAGE_METADATA new handle
      Broker-Configuration-Thread 2014-08-11 14:14:36,248 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase QUEUE_ENTRIES for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:36,739 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase QUEUE_ENTRIES new handle
      Broker-Configuration-Thread 2014-08-11 14:14:36,740 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase XIDS for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:36,975 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:37,976 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Broker-Configuration-Thread 2014-08-11 14:14:38,333 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase XIDS new handle
      Broker-Configuration-Thread 2014-08-11 14:14:38,687 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$10@64066696 is performed successfully with result:BDBHAVirtualHostImpl [id=b125a36b-8e28-417d-9d96-9b5b35344b51, name=group]
      Group-Change-Learner:group:node1 2014-08-11 14:14:38,688 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$8@199d4b18
      Broker-Configuration-Thread 2014-08-11 14:14:38,688 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$8@199d4b18
      Broker-Configuration-Thread 2014-08-11 14:14:38,690 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$8@199d4b18 is performed successfully with result:{virtualhostBlueprint={
        "permittedNodes" : [ "localhost:10000", "localhost:10001" ],
        "type" : "BDB_HA"
      }, virtualhostBlueprintUtilised=true, je.rep.replicaAckTimeout=2 s, je.rep.insufficientReplicasTimeout=2 s}
      main 2014-08-11 14:14:38,727 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Requesting state of the node 'node1' at 'localhost:10000'
      main 2014-08-11 14:14:38,734 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Attribute 'permittedNodes' on node 'node1' is set to '[localhost:10000, localhost:10001]'
      main 2014-08-11 14:14:38,734 DEBUG [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Activating virtualhost node BDBHAVirtualHostNodeImpl [id=5a414a4e-1a51-42eb-a7d5-c6254872873f, name=node2, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node2, groupName=group, address=localhost:10001, state=UNINITIALIZED, priority=1, designatedPrimary=false, quorumOverride=0]
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Creating environment
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment path /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node2
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Group name group
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node name node2
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node host port localhost:10001
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper host port localhost:10000
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper node name node1
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Durability SYNC,NO_SYNC,SIMPLE_MAJORITY
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Designated primary (applicable to 2 node case only) false
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node priority 1
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Quorum override 0
      main 2014-08-11 14:14:38,735 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Permitted node list []
      main 2014-08-11 14:14:38,737 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.repStreamTimeout to '1 h'
      main 2014-08-11 14:14:38,737 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.protocolOldStringEncoding to 'false'
      main 2014-08-11 14:14:38,737 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.logFlushTaskInterval to '1 min'
      main 2014-08-11 14:14:38,737 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envSetupTimeout to '15 min'
      main 2014-08-11 14:14:38,737 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envUnknownStateTimeout to '5 s'
      main 2014-08-11 14:14:38,737 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.replicaAckTimeout to '2 s'
      main 2014-08-11 14:14:38,738 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.insufficientReplicasTimeout to '2 s'
      main 2014-08-11 14:14:38,738 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.stats.collect to 'false'
      main 2014-08-11 14:14:38,738 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.lock.nLockTables to '7'
      Group-Change-Learner:group:node1 2014-08-11 14:14:38,978 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:40,073 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      UNKNOWN node2(-1) 2014-08-11 14:14:40,231 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment is created for node group:node2
      main 2014-08-11 14:14:40,232 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node2' state is REPLICA
      main 2014-08-11 14:14:40,235 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@38478ed2
      Broker-Configuration-Thread 2014-08-11 14:14:40,235 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@38478ed2
      Group-Change-Learner:group:node2 2014-08-11 14:14:40,235 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Received BDB event, new BDB state REPLICA Facade state : OPENING
      Group-Change-Learner:group:node2 2014-08-11 14:14:40,235 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The environment facade is in open state for node group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:14:40,236 INFO [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Received BDB event indicating transition to state REPLICA
      Group-Change-Learner:group:node2 2014-08-11 14:14:40,236 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$10@3cac2b19
      Broker-Configuration-Thread 2014-08-11 14:14:40,237 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@38478ed2 is performed successfully with result:null
      Broker-Configuration-Thread 2014-08-11 14:14:40,237 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$10@3cac2b19
      Broker-Configuration-Thread 2014-08-11 14:14:40,238 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-delivered-group-37
      Broker-Configuration-Thread 2014-08-11 14:14:40,238 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-delivered-group-38
      Broker-Configuration-Thread 2014-08-11 14:14:40,238 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-received-group-39
      Broker-Configuration-Thread 2014-08-11 14:14:40,239 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-received-group-40
      Broker-Configuration-Thread 2014-08-11 14:14:40,245 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$10@3cac2b19 is performed successfully with result:BDBHAReplicaVirtualHost [id=dbff988a-66c9-4fa2-b260-da8c2a891a3d, name=group]
      Group-Change-Learner:group:node1 2014-08-11 14:14:41,075 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:41,077 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Remote replication node added 'Node:node2 localhost:10001 (is member) changeVersion:2 LocalCBVLSN:-1 at:Mon Aug 11 14:14:40 EDT 2014
      ' to 'group'
      Group-Change-Learner:group:node1 2014-08-11 14:14:41,077 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$1@6658c97b
      Broker-Configuration-Thread 2014-08-11 14:14:41,077 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$1@6658c97b
      Broker-Configuration-Thread 2014-08-11 14:14:41,080 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$1@6658c97b is performed successfully with result:null
      Group-Change-Learner:group:node1 2014-08-11 14:14:41,080 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase PINGDB for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:41,107 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase PINGDB new handle
      Group-Change-Learner:group:node1 2014-08-11 14:14:41,113 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=ee94ae5d-c302-42d8-b33c-ee286c1b1de0, name=node2, address=localhost:10001, state=ACTIVE, role=null] updating role to : REPLICA
      main 2014-08-11 14:14:41,152 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing replicated environment facade for group:node2 current state is CLOSING
      Group-Change-Learner:group:node1 2014-08-11 14:14:42,116 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      REPLICA node2(-1) 2014-08-11 14:14:42,116 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node2' state is DETACHED
      REPLICA node2(-1) 2014-08-11 14:14:42,116 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Ignoring the state environment change event as the environment facade for node 'group:node2' is in state CLOSING
      Group-Change-Learner:group:node1 2014-08-11 14:14:42,124 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase PINGDB for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:44,127 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=ee94ae5d-c302-42d8-b33c-ee286c1b1de0, name=node2, address=localhost:10001, state=ACTIVE, role=REPLICA] updating role to : UNKNOWN
      main 2014-08-11 14:14:44,168 DEBUG [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Activating virtualhost node BDBHAVirtualHostNodeImpl [id=5a414a4e-1a51-42eb-a7d5-c6254872873f, name=node2, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node2, groupName=group, address=localhost:10001, state=UNINITIALIZED, priority=1, designatedPrimary=false, quorumOverride=0]
      main 2014-08-11 14:14:44,168 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment at path /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node2 already exists.
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Creating environment
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment path /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node2
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Group name group
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node name node2
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node host port localhost:10001
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper host port localhost:10000
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper node name node1
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Durability SYNC,NO_SYNC,SIMPLE_MAJORITY
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Designated primary (applicable to 2 node case only) false
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node priority 1
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Quorum override 0
      main 2014-08-11 14:14:44,169 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Permitted node list []
      main 2014-08-11 14:14:44,170 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.repStreamTimeout to '1 h'
      main 2014-08-11 14:14:44,171 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.protocolOldStringEncoding to 'false'
      main 2014-08-11 14:14:44,171 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.logFlushTaskInterval to '1 min'
      main 2014-08-11 14:14:44,171 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envSetupTimeout to '15 min'
      main 2014-08-11 14:14:44,171 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envUnknownStateTimeout to '5 s'
      main 2014-08-11 14:14:44,171 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.replicaAckTimeout to '2 s'
      main 2014-08-11 14:14:44,171 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.insufficientReplicasTimeout to '2 s'
      main 2014-08-11 14:14:44,172 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.stats.collect to 'false'
      main 2014-08-11 14:14:44,172 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.lock.nLockTables to '7'
      Group-Change-Learner:group:node1 2014-08-11 14:14:46,564 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:46,569 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=ee94ae5d-c302-42d8-b33c-ee286c1b1de0, name=node2, address=localhost:10001, state=UNAVAILABLE, role=UNKNOWN] updating role to : UNKNOWN
      UNKNOWN node2(-1) 2014-08-11 14:14:47,040 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment is created for node group:node2
      main 2014-08-11 14:14:47,050 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node2' state is REPLICA
      main 2014-08-11 14:14:47,070 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@76fc7475
      Broker-Configuration-Thread 2014-08-11 14:14:47,070 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@76fc7475
      Group-Change-Learner:group:node2 2014-08-11 14:14:47,070 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Received BDB event, new BDB state REPLICA Facade state : OPENING
      Group-Change-Learner:group:node2 2014-08-11 14:14:47,071 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The environment facade is in open state for node group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:14:47,071 INFO [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Received BDB event indicating transition to state REPLICA
      Group-Change-Learner:group:node2 2014-08-11 14:14:47,071 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$10@6f80d790
      Broker-Configuration-Thread 2014-08-11 14:14:47,072 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@76fc7475 is performed successfully with result:null
      Broker-Configuration-Thread 2014-08-11 14:14:47,073 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$10@6f80d790
      Broker-Configuration-Thread 2014-08-11 14:14:47,073 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-delivered-group-41
      Broker-Configuration-Thread 2014-08-11 14:14:47,073 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-delivered-group-42
      Broker-Configuration-Thread 2014-08-11 14:14:47,074 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-received-group-43
      Broker-Configuration-Thread 2014-08-11 14:14:47,074 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-received-group-44
      Broker-Configuration-Thread 2014-08-11 14:14:47,084 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$10@6f80d790 is performed successfully with result:BDBHAReplicaVirtualHost [id=89729f18-5f06-4e4c-b051-277d793311d9, name=group]
      main 2014-08-11 14:14:47,131 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$7@13c6e617
      Broker-Configuration-Thread 2014-08-11 14:14:47,132 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$7@13c6e617
      Broker-Configuration-Thread 2014-08-11 14:14:47,132 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@672bfa25
      Broker-Configuration-Thread 2014-08-11 14:14:47,132 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@672bfa25
      Broker-Configuration-Thread 2014-08-11 14:14:47,132 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Deleting store /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node2
      Broker-Configuration-Thread 2014-08-11 14:14:47,133 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@672bfa25 is performed successfully with result:null
      Broker-Configuration-Thread 2014-08-11 14:14:47,133 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$7@13c6e617 is performed successfully with result:DELETED
      main 2014-08-11 14:14:47,133 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$7@7833c80d
      Broker-Configuration-Thread 2014-08-11 14:14:47,133 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$7@7833c80d
      Broker-Configuration-Thread 2014-08-11 14:14:47,134 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@f930b22
      Broker-Configuration-Thread 2014-08-11 14:14:47,134 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@f930b22
      Broker-Configuration-Thread 2014-08-11 14:14:47,134 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing replicated environment facade for group:node2 current state is CLOSING
      Group-Change-Learner:group:node1 2014-08-11 14:14:47,573 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:47,577 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase PINGDB for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:47,582 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=ee94ae5d-c302-42d8-b33c-ee286c1b1de0, name=node2, address=localhost:10001, state=UNAVAILABLE, role=UNKNOWN] updating role to : REPLICA
      REPLICA node2(2) 2014-08-11 14:14:48,585 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node2' state is DETACHED
      REPLICA node2(2) 2014-08-11 14:14:48,585 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Ignoring the state environment change event as the environment facade for node 'group:node2' is in state CLOSING
      Group-Change-Learner:group:node1 2014-08-11 14:14:48,586 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:14:48,608 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase PINGDB for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:48,694 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Deleting store /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node2
      Broker-Configuration-Thread 2014-08-11 14:14:49,358 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@f930b22 is performed successfully with result:null
      Broker-Configuration-Thread 2014-08-11 14:14:49,358 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$7@7833c80d is performed successfully with result:DELETED
      main 2014-08-11 14:14:49,359 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$7@1112b07f
      Broker-Configuration-Thread 2014-08-11 14:14:49,359 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$7@1112b07f
      Broker-Configuration-Thread 2014-08-11 14:14:49,359 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@62016a9a
      Broker-Configuration-Thread 2014-08-11 14:14:49,359 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@62016a9a
      Broker-Configuration-Thread 2014-08-11 14:14:49,360 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$7@4afdd6ba
      Broker-Configuration-Thread 2014-08-11 14:14:49,360 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$7@4afdd6ba
      Broker-Configuration-Thread 2014-08-11 14:14:49,360 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@5f1c73cc
      Broker-Configuration-Thread 2014-08-11 14:14:49,360 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@5f1c73cc
      Broker-Configuration-Thread 2014-08-11 14:14:49,404 DEBUG [qpid.server.connection.ConnectionRegistry] Closing connection registry :0 connections.
      Broker-Configuration-Thread 2014-08-11 14:14:49,694 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@5f1c73cc is performed successfully with result:null
      Broker-Configuration-Thread 2014-08-11 14:14:49,694 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Removing configured object: b125a36b-8e28-417d-9d96-9b5b35344b51
      Broker-Configuration-Thread 2014-08-11 14:14:49,694 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:49,695 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:49,701 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$7@4afdd6ba is performed successfully with result:DELETED
      Broker-Configuration-Thread 2014-08-11 14:14:49,701 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing replicated environment facade for group:node1 current state is CLOSING
      Group-Change-Learner:group:node1 2014-08-11 14:14:50,611 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Cannot restart environment because of facade state: CLOSING
      Group-Change-Learner:group:node1 2014-08-11 14:14:50,612 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Cannot restart environment because of facade state: CLOSING
      Commit-Thread-group 2014-08-11 14:14:50,614 DEBUG [server.store.berkeleydb.CoalescingCommiter$CommitThread] flushLog completed in 0 ms
      Broker-Configuration-Thread 2014-08-11 14:14:50,615 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing CONFIGURED_OBJECT_HIERARCHY on group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:50,615 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing XIDS on group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:50,616 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing MESSAGE_METADATA on group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:50,616 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing PINGDB on group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:50,616 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing CONFIGURED_OBJECTS on group:node1
      Broker-Configuration-Thread 2014-08-11 14:14:50,616 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing QUEUE_ENTRIES on group:node1
      MASTER node1(1) 2014-08-11 14:14:50,624 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node1' state is DETACHED
      MASTER node1(1) 2014-08-11 14:14:50,624 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Ignoring the state environment change event as the environment facade for node 'group:node1' is in state CLOSING
      Broker-Configuration-Thread 2014-08-11 14:14:50,662 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Deleting store /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node1
      Broker-Configuration-Thread 2014-08-11 14:14:50,665 WARN [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] The deletion of node BDBHAVirtualHostNodeImpl [id=1af44e76-4cb2-43bb-83d7-053586beb749, name=node1, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407780873883/node1, groupName=group, address=localhost:10000, state=DELETED, priority=1, designatedPrimary=true, quorumOverride=0] on remote nodes failed due to: (JE 5.0.97) Could not determine master from helpers at:[localhost/127.0.0.1:10001]. To finish deletion a removal of the node from any of remote nodes ([localhost/127.0.0.1:10001]) is required.
      Broker-Configuration-Thread 2014-08-11 14:14:50,665 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@62016a9a is performed successfully with result:null
      Broker-Configuration-Thread 2014-08-11 14:14:50,665 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$7@1112b07f is performed successfully with result:DELETED
      main 2014-08-11 14:14:50,665 DEBUG [server.configuration.updater.TaskExecutorImpl] Stopping task executor immediately
      main 2014-08-11 14:14:50,667 DEBUG [server.configuration.updater.TaskExecutorImpl] Task executor was stopped immediately. Number of unfinished tasks: 0
      main 2014-08-11 14:14:50,667 INFO [qpid.test.utils.QpidTestCase] ========== tearDown BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached ==========
      

      Another test failure:

      Error Message

      Node node2 did not transit into role [REPLICA]

      Stacktrace

      java.lang.AssertionError: Node node2 did not transit into role [REPLICA]
      	at org.junit.Assert.fail(Assert.java:88)
      	at org.junit.Assert.assertTrue(Assert.java:41)
      	at org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeTestHelper.assertNodeRole(BDBHAVirtualHostNodeTestHelper.java:236)
      	at org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached(BDBHAVirtualHostNodeOperationalLoggingTest.java:363)
      

      Standard Output

      UNKNOWN node2(-1) 2014-08-11 14:34:12,859 INFO [qpid.test.utils.QpidTestCase] ========== start BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached ==========
      UNKNOWN node2(-1) 2014-08-11 14:34:12,864 DEBUG [qpid.server.plugin.QpidServiceLoader] Found 42 implementations of interface org.apache.qpid.server.plugin.ConfiguredObjectTypeFactory
      UNKNOWN node2(-1) 2014-08-11 14:34:12,872 DEBUG [server.configuration.updater.TaskExecutorImpl] Starting task executor
      UNKNOWN node2(-1) 2014-08-11 14:34:12,872 DEBUG [server.configuration.updater.TaskExecutorImpl] Task executor is started
      UNKNOWN node2(-1) 2014-08-11 14:34:12,873 DEBUG [qpid.test.utils.PortHelper] port 10001 is not free
      UNKNOWN node2(-1) 2014-08-11 14:34:12,897 DEBUG [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Activating virtualhost node BDBHAVirtualHostNodeImpl [id=1ee2fa17-934b-428a-b358-280243afe349, name=node1, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node1, groupName=group, address=localhost:10000, state=UNINITIALIZED, priority=1, designatedPrimary=true, quorumOverride=0]
      UNKNOWN node2(-1) 2014-08-11 14:34:12,899 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Creating environment
      UNKNOWN node2(-1) 2014-08-11 14:34:12,899 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment path /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node1
      UNKNOWN node2(-1) 2014-08-11 14:34:12,899 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Group name group
      UNKNOWN node2(-1) 2014-08-11 14:34:12,899 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node name node1
      UNKNOWN node2(-1) 2014-08-11 14:34:12,899 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node host port localhost:10000
      UNKNOWN node2(-1) 2014-08-11 14:34:12,899 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper host port localhost:10000
      UNKNOWN node2(-1) 2014-08-11 14:34:12,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper node name node1
      UNKNOWN node2(-1) 2014-08-11 14:34:12,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Durability SYNC,NO_SYNC,SIMPLE_MAJORITY
      UNKNOWN node2(-1) 2014-08-11 14:34:12,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Designated primary (applicable to 2 node case only) true
      UNKNOWN node2(-1) 2014-08-11 14:34:12,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node priority 1
      UNKNOWN node2(-1) 2014-08-11 14:34:12,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Quorum override 0
      UNKNOWN node2(-1) 2014-08-11 14:34:12,900 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Permitted node list []
      UNKNOWN node2(-1) 2014-08-11 14:34:12,903 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.repStreamTimeout to '1 h'
      UNKNOWN node2(-1) 2014-08-11 14:34:12,904 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.protocolOldStringEncoding to 'false'
      UNKNOWN node2(-1) 2014-08-11 14:34:12,904 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.logFlushTaskInterval to '1 min'
      UNKNOWN node2(-1) 2014-08-11 14:34:12,904 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envSetupTimeout to '15 min'
      UNKNOWN node2(-1) 2014-08-11 14:34:12,905 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envUnknownStateTimeout to '5 s'
      UNKNOWN node2(-1) 2014-08-11 14:34:12,905 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.replicaAckTimeout to '2 s'
      UNKNOWN node2(-1) 2014-08-11 14:34:12,905 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.insufficientReplicasTimeout to '2 s'
      UNKNOWN node2(-1) 2014-08-11 14:34:12,907 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.stats.collect to 'false'
      UNKNOWN node2(-1) 2014-08-11 14:34:12,907 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.lock.nLockTables to '7'
      MASTER node1(1) 2014-08-11 14:34:12,976 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment is created for node group:node1
      UNKNOWN node2(-1) 2014-08-11 14:34:12,977 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node1' state is MASTER
      Group-Change-Learner:group:node1 2014-08-11 14:34:12,979 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Received BDB event, new BDB state MASTER Facade state : OPENING
      Group-Change-Learner:group:node1 2014-08-11 14:34:12,979 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The environment facade is in open state for node group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:12,979 INFO [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Received BDB event indicating transition to state MASTER
      Group-Change-Learner:group:node1 2014-08-11 14:34:12,993 DEBUG [store.berkeleydb.upgrade.Upgrader] Source message store version is 8
      Group-Change-Learner:group:node1 2014-08-11 14:34:12,993 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:12,996 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS new handle
      Group-Change-Learner:group:node1 2014-08-11 14:34:12,997 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:12,997 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,000 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY new handle
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,001 INFO [qpid.server.store.GenericStoreUpgrader] VirtualHost store has model version 2.0. Number of record(s) 0
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,001 DEBUG [qpid.server.store.GenericStoreUpgrader] VirtualHost store upgrade is about to complete. 0 total record(s). Records to update 0 Records to delete 0
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,002 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@5e872bf
      Broker-Configuration-Thread 2014-08-11 14:34:13,002 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@5e872bf
      Broker-Configuration-Thread 2014-08-11 14:34:13,003 DEBUG [qpid.server.store.GenericRecoverer] Recovering the children of BDBHAVirtualHostNodeImpl [id=1ee2fa17-934b-428a-b358-280243afe349, name=node1, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node1, groupName=group, address=localhost:10000, state=ACTIVE, priority=1, designatedPrimary=true, quorumOverride=0]
      Broker-Configuration-Thread 2014-08-11 14:34:13,003 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@5e872bf is performed successfully with result:null
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,003 DEBUG [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Creating new virtualhost with name : group
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,010 DEBUG [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Using virtualhost blueprint {permittedNodes=[localhost:10000, localhost:10002], type=BDB_HA}
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,010 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$10@5a216844
      Broker-Configuration-Thread 2014-08-11 14:34:13,011 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$10@5a216844
      Broker-Configuration-Thread 2014-08-11 14:34:13,012 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-delivered-group-141
      Broker-Configuration-Thread 2014-08-11 14:34:13,013 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-delivered-group-142
      Broker-Configuration-Thread 2014-08-11 14:34:13,013 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-received-group-143
      Broker-Configuration-Thread 2014-08-11 14:34:13,013 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-received-group-144
      Broker-Configuration-Thread 2014-08-11 14:34:13,014 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting permitted nodes to [localhost:10000, localhost:10002]
      Broker-Configuration-Thread 2014-08-11 14:34:13,021 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Create ConfiguredObjectRecord [id=fdbd52e4-68c7-4f7b-a9e4-e574eea95189, type=VirtualHost, attributes={createdBy=null, lastUpdatedTime=1407782053013, createdTime=1407782053013, permittedNodes=[localhost:10000, localhost:10002], lastUpdatedBy=null, name=group, modelVersion=2.0, type=BDB_HA}]
      Broker-Configuration-Thread 2014-08-11 14:34:13,021 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Storing configured object record: ConfiguredObjectRecord [id=fdbd52e4-68c7-4f7b-a9e4-e574eea95189, type=VirtualHost, attributes={createdBy=null, lastUpdatedTime=1407782053013, createdTime=1407782053013, permittedNodes=[localhost:10000, localhost:10002], lastUpdatedBy=null, name=group, modelVersion=2.0, type=BDB_HA}]
      Broker-Configuration-Thread 2014-08-11 14:34:13,024 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,031 DEBUG [qpid.server.plugin.QpidServiceLoader] Found 0 implementations of interface org.apache.qpid.server.plugin.SystemNodeCreator
      Broker-Configuration-Thread 2014-08-11 14:34:13,036 DEBUG [store.berkeleydb.upgrade.Upgrader] Source message store version is 8
      Broker-Configuration-Thread 2014-08-11 14:34:13,039 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,045 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,053 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Create [name=amq.direct, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=9e3882b1-5a59-3b39-9892-c5ee0e733528]
      Broker-Configuration-Thread 2014-08-11 14:34:13,054 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Storing configured object record: [name=amq.direct, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=9e3882b1-5a59-3b39-9892-c5ee0e733528]
      Broker-Configuration-Thread 2014-08-11 14:34:13,059 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,061 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,074 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Create [name=amq.topic, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=13befa16-0b6d-35ef-8d42-e2cae8038115]
      Broker-Configuration-Thread 2014-08-11 14:34:13,075 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Storing configured object record: [name=amq.topic, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=13befa16-0b6d-35ef-8d42-e2cae8038115]
      Broker-Configuration-Thread 2014-08-11 14:34:13,080 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,082 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,089 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Create [name=amq.match, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=dfe1947f-8661-3342-8d44-d9f00e2ca410]
      Broker-Configuration-Thread 2014-08-11 14:34:13,089 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Storing configured object record: [name=amq.match, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=dfe1947f-8661-3342-8d44-d9f00e2ca410]
      Broker-Configuration-Thread 2014-08-11 14:34:13,091 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,092 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,105 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Create [name=amq.fanout, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=9547f9e9-94c5-3e90-bcee-a0aef0399240]
      Broker-Configuration-Thread 2014-08-11 14:34:13,105 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Storing configured object record: [name=amq.fanout, categoryClass=interface org.apache.qpid.server.model.Exchange, type=Exchange, id=9547f9e9-94c5-3e90-bcee-a0aef0399240]
      Broker-Configuration-Thread 2014-08-11 14:34:13,111 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,112 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,116 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase MESSAGE_METADATA for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,120 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase MESSAGE_METADATA new handle
      Broker-Configuration-Thread 2014-08-11 14:34:13,120 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase QUEUE_ENTRIES for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,123 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase QUEUE_ENTRIES new handle
      Broker-Configuration-Thread 2014-08-11 14:34:13,123 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase XIDS for group:node1
      Broker-Configuration-Thread 2014-08-11 14:34:13,126 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase XIDS new handle
      Broker-Configuration-Thread 2014-08-11 14:34:13,128 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$10@5a216844 is performed successfully with result:BDBHAVirtualHostImpl [id=fdbd52e4-68c7-4f7b-a9e4-e574eea95189, name=group]
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,129 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$8@4b7185e8
      Broker-Configuration-Thread 2014-08-11 14:34:13,130 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$8@4b7185e8
      Broker-Configuration-Thread 2014-08-11 14:34:13,135 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$8@4b7185e8 is performed successfully with result:{virtualhostBlueprint={
        "permittedNodes" : [ "localhost:10000", "localhost:10002" ],
        "type" : "BDB_HA"
      }, virtualhostBlueprintUtilised=true, je.rep.replicaAckTimeout=2 s, je.rep.insufficientReplicasTimeout=2 s}
      UNKNOWN node2(-1) 2014-08-11 14:34:13,193 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Requesting state of the node 'node1' at 'localhost:10000'
      UNKNOWN node2(-1) 2014-08-11 14:34:13,198 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Attribute 'permittedNodes' on node 'node1' is set to '[localhost:10002, localhost:10000]'
      UNKNOWN node2(-1) 2014-08-11 14:34:13,199 DEBUG [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Activating virtualhost node BDBHAVirtualHostNodeImpl [id=4aa1e22e-2909-42b8-82f4-64bf57feb3c1, name=node2, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node2, groupName=group, address=localhost:10002, state=UNINITIALIZED, priority=1, designatedPrimary=false, quorumOverride=0]
      UNKNOWN node2(-1) 2014-08-11 14:34:13,199 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Creating environment
      UNKNOWN node2(-1) 2014-08-11 14:34:13,199 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment path /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node2
      UNKNOWN node2(-1) 2014-08-11 14:34:13,199 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Group name group
      UNKNOWN node2(-1) 2014-08-11 14:34:13,199 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node name node2
      UNKNOWN node2(-1) 2014-08-11 14:34:13,199 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node host port localhost:10002
      UNKNOWN node2(-1) 2014-08-11 14:34:13,200 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper host port localhost:10000
      UNKNOWN node2(-1) 2014-08-11 14:34:13,200 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper node name node1
      UNKNOWN node2(-1) 2014-08-11 14:34:13,200 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Durability SYNC,NO_SYNC,SIMPLE_MAJORITY
      UNKNOWN node2(-1) 2014-08-11 14:34:13,200 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Designated primary (applicable to 2 node case only) false
      UNKNOWN node2(-1) 2014-08-11 14:34:13,200 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node priority 1
      UNKNOWN node2(-1) 2014-08-11 14:34:13,200 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Quorum override 0
      UNKNOWN node2(-1) 2014-08-11 14:34:13,200 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Permitted node list []
      UNKNOWN node2(-1) 2014-08-11 14:34:13,201 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.repStreamTimeout to '1 h'
      UNKNOWN node2(-1) 2014-08-11 14:34:13,201 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.protocolOldStringEncoding to 'false'
      UNKNOWN node2(-1) 2014-08-11 14:34:13,201 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.logFlushTaskInterval to '1 min'
      UNKNOWN node2(-1) 2014-08-11 14:34:13,201 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envSetupTimeout to '15 min'
      UNKNOWN node2(-1) 2014-08-11 14:34:13,201 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envUnknownStateTimeout to '5 s'
      UNKNOWN node2(-1) 2014-08-11 14:34:13,202 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.replicaAckTimeout to '2 s'
      UNKNOWN node2(-1) 2014-08-11 14:34:13,202 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.insufficientReplicasTimeout to '2 s'
      UNKNOWN node2(-1) 2014-08-11 14:34:13,202 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.stats.collect to 'false'
      UNKNOWN node2(-1) 2014-08-11 14:34:13,202 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.lock.nLockTables to '7'
      UNKNOWN node2(-1) 2014-08-11 14:34:13,394 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment is created for node group:node2
      UNKNOWN node2(-1) 2014-08-11 14:34:13,396 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node2' state is REPLICA
      UNKNOWN node2(-1) 2014-08-11 14:34:13,397 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@191e8301
      Broker-Configuration-Thread 2014-08-11 14:34:13,398 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@191e8301
      Group-Change-Learner:group:node2 2014-08-11 14:34:13,398 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Received BDB event, new BDB state REPLICA Facade state : OPENING
      Group-Change-Learner:group:node2 2014-08-11 14:34:13,398 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The environment facade is in open state for node group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:13,398 INFO [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Received BDB event indicating transition to state REPLICA
      Group-Change-Learner:group:node2 2014-08-11 14:34:13,398 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$10@725fe50e
      Broker-Configuration-Thread 2014-08-11 14:34:13,402 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@191e8301 is performed successfully with result:null
      Broker-Configuration-Thread 2014-08-11 14:34:13,402 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$10@725fe50e
      Broker-Configuration-Thread 2014-08-11 14:34:13,404 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-delivered-group-145
      Broker-Configuration-Thread 2014-08-11 14:34:13,404 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-delivered-group-146
      Broker-Configuration-Thread 2014-08-11 14:34:13,404 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-received-group-147
      Broker-Configuration-Thread 2014-08-11 14:34:13,404 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-received-group-148
      Broker-Configuration-Thread 2014-08-11 14:34:13,417 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$10@725fe50e is performed successfully with result:BDBHAReplicaVirtualHost [id=c295d271-3868-448c-8fdb-4f976a77e109, name=group]
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,980 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,981 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Remote replication node added 'Node:node2 localhost:10002 (is member) changeVersion:2 LocalCBVLSN:-1 at:Mon Aug 11 14:34:13 EDT 2014
      ' to 'group'
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,981 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$1@75b734cb
      Broker-Configuration-Thread 2014-08-11 14:34:13,981 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$1@75b734cb
      Broker-Configuration-Thread 2014-08-11 14:34:13,983 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$1@75b734cb is performed successfully with result:null
      Group-Change-Learner:group:node1 2014-08-11 14:34:13,989 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase PINGDB for group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:14,004 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase PINGDB new handle
      UNKNOWN node2(-1) 2014-08-11 14:34:14,009 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing replicated environment facade for group:node2 current state is CLOSING
      Group-Change-Learner:group:node1 2014-08-11 14:34:14,011 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=0a2e831d-0612-4bd5-934e-83b065dea77b, name=node2, address=localhost:10002, state=ACTIVE, role=null] updating role to : REPLICA
      RepNode node2(-1) 2014-08-11 14:34:14,772 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node2' state is MASTER
      RepNode node2(-1) 2014-08-11 14:34:14,772 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Ignoring the state environment change event as the environment facade for node 'group:node2' is in state CLOSED
      Group-Change-Learner:group:node1 2014-08-11 14:34:15,015 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:15,020 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase PINGDB for group:node1
      REPLICA node2(-1) 2014-08-11 14:34:15,021 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node2' state is DETACHED
      REPLICA node2(-1) 2014-08-11 14:34:15,021 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Ignoring the state environment change event as the environment facade for node 'group:node2' is in state CLOSING
      Group-Change-Learner:group:node1 2014-08-11 14:34:15,313 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment restarting due to exception (JE 5.0.97) node1(1):/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node1 com.sleepycat.je.rep.stream.MasterStatus$MasterSyncException: Master change. Node master id: node1(1) Group master id: node2(2) MASTER_TO_REPLICA_TRANSITION: This node was a master and must reinitialize internal state to become a replica. The application must close and reopen all Environment handles. Environment is invalid and must be closed.
      com.sleepycat.je.rep.MasterReplicaTransitionException: (JE 5.0.97) node1(1):/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node1 com.sleepycat.je.rep.stream.MasterStatus$MasterSyncException: Master change. Node master id: node1(1) Group master id: node2(2) MASTER_TO_REPLICA_TRANSITION: This node was a master and must reinitialize internal state to become a replica. The application must close and reopen all Environment handles. Environment is invalid and must be closed.
      	at com.sleepycat.je.rep.impl.node.FeederManager.runFeeders(FeederManager.java:458)
      	at com.sleepycat.je.rep.impl.node.RepNode.run(RepNode.java:1463)
      Caused by: com.sleepycat.je.rep.stream.MasterStatus$MasterSyncException: Master change. Node master id: node1(1) Group master id: node2(2)
      	at com.sleepycat.je.rep.stream.MasterStatus.assertSync(MasterStatus.java:107)
      	at com.sleepycat.je.rep.impl.node.FeederManager.runFeeders(FeederManager.java:390)
      	... 1 more
      Group-Change-Learner:group:node1 2014-08-11 14:34:15,316 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Cannot restart environment because of facade state: RESTARTING
      Group-Change-Learner:group:node1 2014-08-11 14:34:15,316 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=0a2e831d-0612-4bd5-934e-83b065dea77b, name=node2, address=localhost:10002, state=ACTIVE, role=REPLICA] updating role to : UNKNOWN
      Environment-group:node1 2014-08-11 14:34:15,318 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Restarting environment
      Environment-group:node1 2014-08-11 14:34:15,321 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing CONFIGURED_OBJECT_HIERARCHY on group:node1
      Environment-group:node1 2014-08-11 14:34:15,321 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing XIDS on group:node1
      Environment-group:node1 2014-08-11 14:34:15,321 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing MESSAGE_METADATA on group:node1
      Environment-group:node1 2014-08-11 14:34:15,321 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing PINGDB on group:node1
      Environment-group:node1 2014-08-11 14:34:15,322 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing CONFIGURED_OBJECTS on group:node1
      Environment-group:node1 2014-08-11 14:34:15,322 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing QUEUE_ENTRIES on group:node1
      MASTER node1(1) 2014-08-11 14:34:15,327 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node1' state is DETACHED
      Group-Change-Learner:group:node1 2014-08-11 14:34:15,330 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Received BDB event, new BDB state DETACHED Facade state : RESTARTING
      Group-Change-Learner:group:node1 2014-08-11 14:34:15,330 INFO [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Received BDB event indicating transition to state DETACHED
      Environment-group:node1 2014-08-11 14:34:15,331 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Creating environment
      Environment-group:node1 2014-08-11 14:34:15,331 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment path /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:15,331 DEBUG [qpid.server.connection.ConnectionRegistry] Closing connection registry :0 connections.
      Environment-group:node1 2014-08-11 14:34:15,331 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Group name group
      Environment-group:node1 2014-08-11 14:34:15,331 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node name node1
      Environment-group:node1 2014-08-11 14:34:15,331 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node host port localhost:10000
      Environment-group:node1 2014-08-11 14:34:15,332 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper host port localhost:10000
      Environment-group:node1 2014-08-11 14:34:15,332 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper node name node1
      Environment-group:node1 2014-08-11 14:34:15,332 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Durability SYNC,NO_SYNC,SIMPLE_MAJORITY
      Environment-group:node1 2014-08-11 14:34:15,332 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Designated primary (applicable to 2 node case only) true
      Environment-group:node1 2014-08-11 14:34:15,332 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node priority 1
      Environment-group:node1 2014-08-11 14:34:15,332 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Quorum override 0
      Environment-group:node1 2014-08-11 14:34:15,332 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Permitted node list [localhost:10000, localhost:10002]
      Group-Change-Learner:group:node1 2014-08-11 14:34:15,335 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$10@3744a82d
      Broker-Configuration-Thread 2014-08-11 14:34:15,336 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$10@3744a82d
      Environment-group:node1 2014-08-11 14:34:15,338 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.repStreamTimeout to '1 h'
      Broker-Configuration-Thread 2014-08-11 14:34:15,338 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-delivered-group-149
      Environment-group:node1 2014-08-11 14:34:15,338 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.protocolOldStringEncoding to 'false'
      Broker-Configuration-Thread 2014-08-11 14:34:15,339 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-delivered-group-150
      Environment-group:node1 2014-08-11 14:34:15,339 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.logFlushTaskInterval to '1 min'
      Broker-Configuration-Thread 2014-08-11 14:34:15,339 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-received-group-151
      Environment-group:node1 2014-08-11 14:34:15,339 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envSetupTimeout to '15 min'
      Environment-group:node1 2014-08-11 14:34:15,339 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envUnknownStateTimeout to '5 s'
      Environment-group:node1 2014-08-11 14:34:15,339 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.replicaAckTimeout to '2 s'
      Environment-group:node1 2014-08-11 14:34:15,340 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.insufficientReplicasTimeout to '2 s'
      Broker-Configuration-Thread 2014-08-11 14:34:15,339 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-received-group-152
      Environment-group:node1 2014-08-11 14:34:15,340 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.stats.collect to 'false'
      Environment-group:node1 2014-08-11 14:34:15,340 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.lock.nLockTables to '7'
      Broker-Configuration-Thread 2014-08-11 14:34:15,374 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$10@3744a82d is performed successfully with result:BDBHAReplicaVirtualHost [id=3bc489d5-2f3c-4a34-8d4c-96df267d0c76, name=group]
      UNKNOWN node2(-1) 2014-08-11 14:34:15,384 DEBUG [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Activating virtualhost node BDBHAVirtualHostNodeImpl [id=4aa1e22e-2909-42b8-82f4-64bf57feb3c1, name=node2, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node2, groupName=group, address=localhost:10002, state=UNINITIALIZED, priority=1, designatedPrimary=false, quorumOverride=0]
      UNKNOWN node2(-1) 2014-08-11 14:34:15,384 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment at path /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node2 already exists.
      UNKNOWN node2(-1) 2014-08-11 14:34:15,385 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Creating environment
      UNKNOWN node2(-1) 2014-08-11 14:34:15,385 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment path /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node2
      UNKNOWN node2(-1) 2014-08-11 14:34:15,385 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Group name group
      UNKNOWN node2(-1) 2014-08-11 14:34:15,385 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node name node2
      UNKNOWN node2(-1) 2014-08-11 14:34:15,385 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node host port localhost:10002
      UNKNOWN node2(-1) 2014-08-11 14:34:15,386 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper host port localhost:10000
      UNKNOWN node2(-1) 2014-08-11 14:34:15,386 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Helper node name node1
      UNKNOWN node2(-1) 2014-08-11 14:34:15,386 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Durability SYNC,NO_SYNC,SIMPLE_MAJORITY
      UNKNOWN node2(-1) 2014-08-11 14:34:15,386 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Designated primary (applicable to 2 node case only) false
      UNKNOWN node2(-1) 2014-08-11 14:34:15,386 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Node priority 1
      UNKNOWN node2(-1) 2014-08-11 14:34:15,386 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Quorum override 0
      UNKNOWN node2(-1) 2014-08-11 14:34:15,386 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Permitted node list []
      UNKNOWN node2(-1) 2014-08-11 14:34:15,389 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.repStreamTimeout to '1 h'
      UNKNOWN node2(-1) 2014-08-11 14:34:15,389 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.protocolOldStringEncoding to 'false'
      UNKNOWN node2(-1) 2014-08-11 14:34:15,390 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.logFlushTaskInterval to '1 min'
      UNKNOWN node2(-1) 2014-08-11 14:34:15,390 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envSetupTimeout to '15 min'
      UNKNOWN node2(-1) 2014-08-11 14:34:15,390 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.envUnknownStateTimeout to '5 s'
      UNKNOWN node2(-1) 2014-08-11 14:34:15,390 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.replicaAckTimeout to '2 s'
      UNKNOWN node2(-1) 2014-08-11 14:34:15,390 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting ReplicationConfig key je.rep.insufficientReplicasTimeout to '2 s'
      UNKNOWN node2(-1) 2014-08-11 14:34:15,392 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.stats.collect to 'false'
      UNKNOWN node2(-1) 2014-08-11 14:34:15,392 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting EnvironmentConfig key je.lock.nLockTables to '7'
      UNKNOWN node2(-1) 2014-08-11 14:34:17,481 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment is created for node group:node2
      UNKNOWN node2(-1) 2014-08-11 14:34:17,481 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node2' state is MASTER
      UNKNOWN node2(-1) 2014-08-11 14:34:17,482 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@52b1ced0
      Group-Change-Learner:group:node2 2014-08-11 14:34:17,482 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Received BDB event, new BDB state MASTER Facade state : OPENING
      Broker-Configuration-Thread 2014-08-11 14:34:17,482 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@52b1ced0
      Group-Change-Learner:group:node2 2014-08-11 14:34:17,482 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The environment facade is in open state for node group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:17,483 INFO [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Received BDB event indicating transition to state MASTER
      Broker-Configuration-Thread 2014-08-11 14:34:17,490 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl$RemoteNodesDiscoverer$2@52b1ced0 is performed successfully with result:null
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,483 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,489 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase PINGDB for group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,515 DEBUG [store.berkeleydb.upgrade.Upgrader] Source message store version is 8
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,515 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,516 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase PINGDB new handle
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,517 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS new handle
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,519 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,534 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,536 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY new handle
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,540 INFO [qpid.server.store.GenericStoreUpgrader] VirtualHost store has model version 2.0. Number of record(s) 5
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,540 DEBUG [qpid.server.store.GenericStoreUpgrader] VirtualHost store upgrade is about to complete. 5 total record(s). Records to update 0 Records to delete 0
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,541 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@780f8a49
      Broker-Configuration-Thread 2014-08-11 14:34:18,544 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@780f8a49
      Broker-Configuration-Thread 2014-08-11 14:34:18,545 DEBUG [qpid.server.store.GenericRecoverer] Recovering the children of BDBHAVirtualHostNodeImpl [id=4aa1e22e-2909-42b8-82f4-64bf57feb3c1, name=node2, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node2, groupName=group, address=localhost:10002, state=ACTIVE, priority=1, designatedPrimary=false, quorumOverride=0]
      Broker-Configuration-Thread 2014-08-11 14:34:18,546 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-delivered-group-153
      Broker-Configuration-Thread 2014-08-11 14:34:18,546 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-delivered-group-154
      Broker-Configuration-Thread 2014-08-11 14:34:18,546 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-received-group-155
      Broker-Configuration-Thread 2014-08-11 14:34:18,546 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-received-group-156
      Broker-Configuration-Thread 2014-08-11 14:34:18,548 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@780f8a49 is performed successfully with result:null
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,548 DEBUG [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Recovered virtualhost with name : group
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,549 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Setting permitted nodes to [localhost:10000, localhost:10002]
      UNKNOWN node1(-1) 2014-08-11 14:34:18,571 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment is created for node group:node1
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,578 DEBUG [qpid.server.plugin.QpidServiceLoader] Found 0 implementations of interface org.apache.qpid.server.plugin.SystemNodeCreator
      UNKNOWN node1(-1) 2014-08-11 14:34:18,579 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node1' state is REPLICA
      Group-Change-Learner:group:node1 2014-08-11 14:34:18,579 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Received BDB event, new BDB state REPLICA Facade state : RESTARTING
      Group-Change-Learner:group:node1 2014-08-11 14:34:18,579 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The environment facade is in open state for node group:node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:18,579 INFO [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Received BDB event indicating transition to state REPLICA
      Group-Change-Learner:group:node1 2014-08-11 14:34:18,580 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$10@580c9f9d
      UNKNOWN node1(-1) 2014-08-11 14:34:18,580 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Environment is restarted
      Broker-Configuration-Thread 2014-08-11 14:34:18,580 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$10@580c9f9d
      Broker-Configuration-Thread 2014-08-11 14:34:18,582 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-delivered-group-157
      Broker-Configuration-Thread 2014-08-11 14:34:18,582 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-delivered-group-158
      Broker-Configuration-Thread 2014-08-11 14:34:18,583 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: messages-received-group-159
      Broker-Configuration-Thread 2014-08-11 14:34:18,583 INFO [qpid.server.stats.StatisticsCounter] Resetting statistics for counter: bytes-received-group-160
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,590 DEBUG [store.berkeleydb.upgrade.Upgrader] Source message store version is 8
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,592 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECTS for group:node2
      Broker-Configuration-Thread 2014-08-11 14:34:18,593 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$10@580c9f9d is performed successfully with result:BDBHAReplicaVirtualHost [id=4be3da30-67ad-4e83-8ac2-d853466f32ee, name=group]
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,616 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase CONFIGURED_OBJECT_HIERARCHY for group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,618 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase MESSAGE_METADATA for group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,621 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase MESSAGE_METADATA new handle
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,621 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase QUEUE_ENTRIES for group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,623 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase QUEUE_ENTRIES new handle
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,624 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase XIDS for group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:18,625 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase XIDS new handle
      Group-Change-Learner:group:node1 2014-08-11 14:34:19,325 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:19,331 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=0a2e831d-0612-4bd5-934e-83b065dea77b, name=node2, address=localhost:10002, state=UNAVAILABLE, role=UNKNOWN] updating role to : MASTER
      Group-Change-Learner:group:node2 2014-08-11 14:34:19,518 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:19,524 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] openDatabase PINGDB for group:node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:19,533 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=54bb0154-ad89-44d9-805b-f4ee9ae7c3ad, name=node1, address=localhost:10000, state=ACTIVE, role=null] updating role to : REPLICA
      Group-Change-Learner:group:node1 2014-08-11 14:34:20,338 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:20,344 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=0a2e831d-0612-4bd5-934e-83b065dea77b, name=node2, address=localhost:10002, state=ACTIVE, role=MASTER] updating role to : MASTER
      Group-Change-Learner:group:node2 2014-08-11 14:34:20,535 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:20,540 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=54bb0154-ad89-44d9-805b-f4ee9ae7c3ad, name=node1, address=localhost:10000, state=ACTIVE, role=REPLICA] updating role to : REPLICA
      Group-Change-Learner:group:node1 2014-08-11 14:34:21,354 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:21,358 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=0a2e831d-0612-4bd5-934e-83b065dea77b, name=node2, address=localhost:10002, state=ACTIVE, role=MASTER] updating role to : MASTER
      Group-Change-Learner:group:node2 2014-08-11 14:34:21,542 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:21,547 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=54bb0154-ad89-44d9-805b-f4ee9ae7c3ad, name=node1, address=localhost:10000, state=ACTIVE, role=REPLICA] updating role to : REPLICA
      Group-Change-Learner:group:node1 2014-08-11 14:34:22,362 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:22,367 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=0a2e831d-0612-4bd5-934e-83b065dea77b, name=node2, address=localhost:10002, state=ACTIVE, role=MASTER] updating role to : MASTER
      Group-Change-Learner:group:node2 2014-08-11 14:34:22,549 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node2
      Group-Change-Learner:group:node2 2014-08-11 14:34:22,555 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=54bb0154-ad89-44d9-805b-f4ee9ae7c3ad, name=node1, address=localhost:10000, state=ACTIVE, role=REPLICA] updating role to : REPLICA
      UNKNOWN node2(-1) 2014-08-11 14:34:22,644 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$7@141f264
      Broker-Configuration-Thread 2014-08-11 14:34:22,644 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$7@141f264
      Broker-Configuration-Thread 2014-08-11 14:34:22,645 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@109083e1
      Broker-Configuration-Thread 2014-08-11 14:34:22,645 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@109083e1
      Broker-Configuration-Thread 2014-08-11 14:34:22,647 DEBUG [qpid.server.connection.ConnectionRegistry] Closing connection registry :0 connections.
      Broker-Configuration-Thread 2014-08-11 14:34:22,648 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing replicated environment facade for group:node2 current state is CLOSING
      Group-Change-Learner:group:node1 2014-08-11 14:34:23,374 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:23,380 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=0a2e831d-0612-4bd5-934e-83b065dea77b, name=node2, address=localhost:10002, state=ACTIVE, role=MASTER] updating role to : MASTER
      Commit-Thread-group 2014-08-11 14:34:23,563 DEBUG [server.store.berkeleydb.CoalescingCommiter$CommitThread] flushLog completed in 6 ms
      Broker-Configuration-Thread 2014-08-11 14:34:23,563 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing CONFIGURED_OBJECT_HIERARCHY on group:node2
      Broker-Configuration-Thread 2014-08-11 14:34:23,565 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing XIDS on group:node2
      Broker-Configuration-Thread 2014-08-11 14:34:23,566 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing MESSAGE_METADATA on group:node2
      Broker-Configuration-Thread 2014-08-11 14:34:23,566 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing PINGDB on group:node2
      Broker-Configuration-Thread 2014-08-11 14:34:23,567 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing CONFIGURED_OBJECTS on group:node2
      Broker-Configuration-Thread 2014-08-11 14:34:23,568 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing QUEUE_ENTRIES on group:node2
      Group-Change-Learner:group:node1 2014-08-11 14:34:24,387 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Checking for changes in the group group on node node1
      Group-Change-Learner:group:node1 2014-08-11 14:34:24,391 DEBUG [server.virtualhostnode.berkeleydb.BDBHARemoteReplicationNodeImpl] BDBHARemoteReplicationNodeImpl[id=0a2e831d-0612-4bd5-934e-83b065dea77b, name=node2, address=localhost:10002, state=ACTIVE, role=MASTER] updating role to : UNKNOWN
      REPLICA node1(1) 2014-08-11 14:34:24,541 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node1' state is UNKNOWN
      Group-Change-Learner:group:node1 2014-08-11 14:34:24,543 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Received BDB event, new BDB state UNKNOWN Facade state : OPEN
      Group-Change-Learner:group:node1 2014-08-11 14:34:24,543 INFO [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] Received BDB event indicating transition to state UNKNOWN
      MASTER node2(2) 2014-08-11 14:34:24,550 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node2' state is DETACHED
      MASTER node2(2) 2014-08-11 14:34:24,551 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Ignoring the state environment change event as the environment facade for node 'group:node2' is in state CLOSING
      Broker-Configuration-Thread 2014-08-11 14:34:24,577 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Deleting store /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node2
      Broker-Configuration-Thread 2014-08-11 14:34:24,587 WARN [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] The deletion of node BDBHAVirtualHostNodeImpl [id=4aa1e22e-2909-42b8-82f4-64bf57feb3c1, name=node2, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node2, groupName=group, address=localhost:10002, state=DELETED, priority=1, designatedPrimary=false, quorumOverride=0] on remote nodes failed due to: (JE 5.0.97) Could not determine master from helpers at:[localhost/127.0.0.1:10000]. To finish deletion a removal of the node from any of remote nodes ([localhost/127.0.0.1:10000]) is required.
      Broker-Configuration-Thread 2014-08-11 14:34:24,588 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@109083e1 is performed successfully with result:null
      Broker-Configuration-Thread 2014-08-11 14:34:24,588 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$7@141f264 is performed successfully with result:DELETED
      UNKNOWN node2(-1) 2014-08-11 14:34:24,589 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$7@735035de
      Broker-Configuration-Thread 2014-08-11 14:34:24,591 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$7@735035de
      Broker-Configuration-Thread 2014-08-11 14:34:24,591 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@317607ed
      Broker-Configuration-Thread 2014-08-11 14:34:24,592 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@317607ed
      Broker-Configuration-Thread 2014-08-11 14:34:24,593 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Deleting store /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node2
      Broker-Configuration-Thread 2014-08-11 14:34:24,594 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@317607ed is performed successfully with result:null
      Broker-Configuration-Thread 2014-08-11 14:34:24,594 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$7@735035de is performed successfully with result:DELETED
      UNKNOWN node2(-1) 2014-08-11 14:34:24,594 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.model.AbstractConfiguredObject$7@3c0271f9
      Broker-Configuration-Thread 2014-08-11 14:34:24,595 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.model.AbstractConfiguredObject$7@3c0271f9
      Broker-Configuration-Thread 2014-08-11 14:34:24,596 DEBUG [server.configuration.updater.TaskExecutorImpl] Submitting task: org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@4488b136
      Broker-Configuration-Thread 2014-08-11 14:34:24,596 DEBUG [server.configuration.updater.TaskExecutorImpl] Performing task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@4488b136
      Broker-Configuration-Thread 2014-08-11 14:34:24,597 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Closing replicated environment facade for group:node1 current state is CLOSING
      Commit-Thread-group 2014-08-11 14:34:25,403 DEBUG [server.store.berkeleydb.CoalescingCommiter$CommitThread] flushLog completed in 9 ms
      UNKNOWN node1(1) 2014-08-11 14:34:25,417 INFO [store.berkeleydb.replication.ReplicatedEnvironmentFacade] The node 'group:node1' state is DETACHED
      UNKNOWN node1(1) 2014-08-11 14:34:25,417 DEBUG [store.berkeleydb.replication.ReplicatedEnvironmentFacade] Ignoring the state environment change event as the environment facade for node 'group:node1' is in state CLOSING
      Broker-Configuration-Thread 2014-08-11 14:34:25,446 DEBUG [server.store.berkeleydb.BDBConfigurationStore] Deleting store /tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node1
      Broker-Configuration-Thread 2014-08-11 14:34:25,450 WARN [server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl] The deletion of node BDBHAVirtualHostNodeImpl [id=1ee2fa17-934b-428a-b358-280243afe349, name=node1, storePath=/tmp/BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached.1407782052872/node1, groupName=group, address=localhost:10000, state=DELETED, priority=1, designatedPrimary=true, quorumOverride=0] on remote nodes failed due to: (JE 5.0.97) Could not determine master from helpers at:[localhost/127.0.0.1:10002]. To finish deletion a removal of the node from any of remote nodes ([localhost/127.0.0.1:10002]) is required.
      Broker-Configuration-Thread 2014-08-11 14:34:25,451 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2@4488b136 is performed successfully with result:null
      Broker-Configuration-Thread 2014-08-11 14:34:25,451 DEBUG [server.configuration.updater.TaskExecutorImpl] Task org.apache.qpid.server.model.AbstractConfiguredObject$7@3c0271f9 is performed successfully with result:DELETED
      UNKNOWN node2(-1) 2014-08-11 14:34:25,451 DEBUG [server.configuration.updater.TaskExecutorImpl] Stopping task executor immediately
      UNKNOWN node2(-1) 2014-08-11 14:34:25,453 DEBUG [server.configuration.updater.TaskExecutorImpl] Task executor was stopped immediately. Number of unfinished tasks: 0
      UNKNOWN node2(-1) 2014-08-11 14:34:25,453 INFO [qpid.test.utils.QpidTestCase] ========== tearDown BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached ==========
      

        Attachments

          Activity

            People

            • Assignee:
              macbean Andrew MacBean
              Reporter:
              orudyy Alex Rudyy
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: