qpid-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "ASF subversion and git services (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (QPID-5994) [Java Broker]Test BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached fails sporadically
Date Wed, 13 Aug 2014 14:29:14 GMT

    [ https://issues.apache.org/jira/browse/QPID-5994?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14095532#comment-14095532 ] 

ASF subversion and git services commented on QPID-5994:
-------------------------------------------------------

Commit 1617736 from orudyy@apache.org in branch 'qpid/trunk'
[ https://svn.apache.org/r1617736 ]

QPID-5994: Fix ocasionally failing test BDBHAVirtualHostNodeOperationalLoggingTest.testRemoteNodeReAttached

> [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-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org


Mime
View raw message