[jira] [Updated] (QPID-5994) [Java Broker]Test BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached fails sporadically

[Alex Rudyy (JIRA)]

     [ 
https://issues.apache.org/jira/browse/QPID-5994?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Alex Rudyy updated QPID-5994:
-----------------------------

    Status: Reviewable  (was: In Progress)

> [Java Broker]Test 
> BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached fails 
> sporadically
> --------------------------------------------------------------------------------------------------------
>
>                 Key: QPID-5994
>                 URL: https://issues.apache.org/jira/browse/QPID-5994
>             Project: Qpid
>          Issue Type: Bug
>          Components: Java Broker
>            Reporter: Alex Rudyy
>            Assignee: Alex Rudyy
>             Fix For: 0.30
>
>
> 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
> {noformat}
> 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)
> {noformat}
> Standard Output
> {noformat}
> 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 
> ==========
> {noformat}
> Another test failure:
> Error Message
> Node node2 did not transit into role [REPLICA]
> Stacktrace
> {noformat}
> 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)
> {noformat}
> Standard Output
> {noformat}
> 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 ==========
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.2#6252)

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@qpid.apache.org
For additional commands, e-mail: dev-h...@qpid.apache.org