You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2015/11/06 22:31:45 UTC
[JENKINS] Lucene-Solr-5.x-Linux (32bit/jdk1.8.0_66) - Build # 14522
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-5.x-Linux/14522/
Java: 32bit/jdk1.8.0_66 -server -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: org.apache.solr.cloud.OverseerTest.testOverseerStatsReset
Error Message:
expected:<1> but was:<2>
Stack Trace:
java.lang.AssertionError: expected:<1> but was:<2>
at __randomizedtesting.SeedInfo.seed([33AD9326861AACB1:98F9741A13C00FBF]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.junit.Assert.assertEquals(Assert.java:456)
at org.apache.solr.cloud.OverseerTest.testOverseerStatsReset(OverseerTest.java:722)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1660)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:866)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:902)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:809)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:460)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:875)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:777)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:811)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:822)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:54)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 9877 lines...]
[junit4] Suite: org.apache.solr.cloud.OverseerTest
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-5.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.OverseerTest_33AD9326861AACB1-001/init-core-data-001
[junit4] 2> 19042 INFO (SUITE-OverseerTest-seed#[33AD9326861AACB1]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false)
[junit4] 2> 19042 INFO (SUITE-OverseerTest-seed#[33AD9326861AACB1]-worker) [ ] o.a.s.SolrTestCaseJ4 ####initCore
[junit4] 2> 19042 INFO (SUITE-OverseerTest-seed#[33AD9326861AACB1]-worker) [ ] o.a.s.SolrTestCaseJ4 ####initCore end
[junit4] 2> 19044 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testPlaceholders
[junit4] 2> 19044 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 19044 INFO (Thread-122) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 19044 INFO (Thread-122) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 19144 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ZkTestServer start zk server on port:42412
[junit4] 2> 19144 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 19144 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 19147 INFO (zkCallback-18-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@158b752 name:ZooKeeperConnection Watcher:127.0.0.1:42412/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 19147 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 19148 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 19148 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 19149 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 19150 INFO (zkCallback-19-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@b5619c name:ZooKeeperConnection Watcher:127.0.0.1:42412 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 19150 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 19150 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 19151 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 19151 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 19152 INFO (zkCallback-20-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@9b53d8 name:ZooKeeperConnection Watcher:127.0.0.1:42412 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 19152 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 19152 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 19152 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /solr
[junit4] 2> 19154 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /live_nodes
[junit4] 2> 19155 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections
[junit4] 2> 19156 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /aliases.json
[junit4] 2> 19156 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /clusterstate.json
[junit4] 2> 19157 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /security.json
[junit4] 2> 19157 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 19158 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 19159 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 19160 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@1eae595 name:ZooKeeperConnection Watcher:127.0.0.1:42412/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 19160 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 19160 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 19161 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 19162 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /live_nodes/node1
[junit4] 2> 19162 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 0)
[junit4] 2> 19162 INFO (zkCallback-18-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 0)
[junit4] 2> 19163 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 19163 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 19164 INFO (zkCallback-22-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@172763e name:ZooKeeperConnection Watcher:127.0.0.1:42412/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 19164 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 19164 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 19164 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=600000&connTimeout=60000&retry=true
[junit4] 2> 19167 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer_elect
[junit4] 2> 19168 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer_elect/election
[junit4] 2> 19169 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 19169 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /overseer_elect/election/94820355599368196-127.0.0.1:42412_solr-n_0000000000
[junit4] 2> 19170 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:42412_solr
[junit4] 2> 19170 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer_elect/leader
[junit4] 2> 19171 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.Overseer Overseer (id=94820355599368196-127.0.0.1:42412_solr-n_0000000000) starting
[junit4] 2> 19172 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/queue
[junit4] 2> 19173 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/queue-work
[junit4] 2> 19174 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-map-failure
[junit4] 2> 19177 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-map-running
[junit4] 2> 19178 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-map-completed
[junit4] 2> 19180 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-queue-work
[junit4] 2> 19181 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.OverseerAutoReplicaFailoverThread Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 19182 INFO (OverseerCollectionConfigSetProcessor-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskProcessor Process current queue of overseer operations
[junit4] 2> 19182 INFO (OverseerStateUpdate-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.Overseer Starting to work on the main queue
[junit4] 2> 19182 INFO (OverseerStateUpdate-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 19192 INFO (OverseerStateUpdate-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"12",
[junit4] 2> "base_url":"http://node1/solr/"} current state version: 0
[junit4] 2> 19198 INFO (OverseerStateUpdate-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=12 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"12",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 19199 INFO (OverseerStateUpdate-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.o.ClusterStateMutator building a new cName: collection1
[junit4] 2> 19208 INFO (OverseerStateUpdate-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 19210 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 19210 INFO (zkCallback-18-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 19210 INFO (zkCallback-22-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 19691 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 19692 INFO (zkCallback-18-thread-1) [ ] o.a.s.c.c.ZkStateReader A collections change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/collections, has occurred - updating...
[junit4] 2> 19692 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader A collections change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/collections, has occurred - updating...
[junit4] 2> 19692 INFO (zkCallback-22-thread-2) [ ] o.a.s.c.c.ZkStateReader A collections change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/collections, has occurred - updating...
[junit4] 2> 19696 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /collections/collection1/leader_elect/shard2/election/94820355599368195-node1_core1-n_0000000000
[junit4] 2> 19698 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/leaders/shard2
[junit4] 2> 19701 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ShardLeaderElectionContextBase Creating leader registration node
[junit4] 2> 19712 INFO (OverseerStateUpdate-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "shard":"shard2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "base_url":"http://node1/solr/",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "core":"core1"} current state version: 1
[junit4] 2> 19713 INFO (OverseerStateUpdate-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "shard":"shard2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "base_url":"http://node1/solr/",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "core":"core1"}
[junit4] 2> 19715 INFO (zkCallback-18-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 19715 INFO (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 21190 INFO (OverseerCollectionConfigSetProcessor-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskProcessor
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:345)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:61)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor.amILeader(OverseerTaskProcessor.java:355)
[junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor.run(OverseerTaskProcessor.java:172)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 21190 INFO (OverseerCollectionConfigSetProcessor-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskProcessor According to ZK I (id=94820355599368196-127.0.0.1:42412_solr-n_0000000000) am no longer a leader.
[junit4] 2> 21215 WARN (OverseerStateUpdate-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.Overseer Solr cannot talk to ZK, exiting Overseer main queue loop
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer/queue
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1472)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:328)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:325)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:61)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:325)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.fetchZkChildren(DistributedQueue.java:311)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.firstChild(DistributedQueue.java:290)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.firstElement(DistributedQueue.java:359)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.peek(DistributedQueue.java:166)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:233)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 21215 WARN (zkCallback-21-thread-1) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 21215 INFO (OverseerStateUpdate-94820355599368196-127.0.0.1:42412_solr-n_0000000000) [ ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:42412_solr
[junit4] 2> 21216 ERROR (OverseerExitThread) [ ] o.a.s.c.Overseer could not read the data
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:345)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:61)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:87)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$2.run(Overseer.java:265)
[junit4] 2> 21217 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:42412 42412
[junit4] 2> 21317 INFO (Thread-122) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:42412 42412
[junit4] 2> 21319 WARN (Thread-122) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/aliases.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/clusterstate.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/live_nodes
[junit4] 2> 3 /solr/collections
[junit4] 2>
[junit4] 2> 21324 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testPlaceholders
[junit4] 2> 21324 INFO (TEST-OverseerTest.testPlaceholders-seed#[33AD9326861AACB1]) [ ] o.a.s.c.Overseer Overseer (id=94820355599368196-127.0.0.1:42412_solr-n_0000000000) closing
[junit4] 2> 21327 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDoubleAssignment
[junit4] 2> 21328 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 21328 INFO (Thread-123) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 21328 INFO (Thread-123) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 21428 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ZkTestServer start zk server on port:36447
[junit4] 2> 21428 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 21429 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 21433 INFO (zkCallback-24-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@f12d82 name:ZooKeeperConnection Watcher:127.0.0.1:36447/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 21433 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 21433 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 21433 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 21434 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 21436 INFO (zkCallback-25-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@6d9d5 name:ZooKeeperConnection Watcher:127.0.0.1:36447 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 21436 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 21436 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 21437 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 21438 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 21448 INFO (zkCallback-26-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@dd4aaa name:ZooKeeperConnection Watcher:127.0.0.1:36447 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 21448 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 21449 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 21449 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /solr
[junit4] 2> 21451 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /live_nodes
[junit4] 2> 21452 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections
[junit4] 2> 21453 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /aliases.json
[junit4] 2> 21454 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /clusterstate.json
[junit4] 2> 21455 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /security.json
[junit4] 2> 21455 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 21456 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 21457 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 21458 INFO (zkCallback-27-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@4b1d0 name:ZooKeeperConnection Watcher:127.0.0.1:36447/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 21458 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 21459 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 21460 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 21461 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /live_nodes/node1
[junit4] 2> 21462 INFO (zkCallback-24-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 0)
[junit4] 2> 21462 INFO (zkCallback-27-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 0)
[junit4] 2> 21471 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 21472 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 21482 INFO (zkCallback-28-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@da8c38 name:ZooKeeperConnection Watcher:127.0.0.1:36447/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 21482 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 21482 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 21483 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=600000&connTimeout=60000&retry=true
[junit4] 2> 21485 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer_elect
[junit4] 2> 21486 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer_elect/election
[junit4] 2> 21486 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 21491 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /overseer_elect/election/94820355749249028-127.0.0.1:36447_solr-n_0000000000
[junit4] 2> 21495 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:36447_solr
[junit4] 2> 21495 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer_elect/leader
[junit4] 2> 21497 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.Overseer Overseer (id=94820355749249028-127.0.0.1:36447_solr-n_0000000000) starting
[junit4] 2> 21498 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/queue
[junit4] 2> 21499 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/queue-work
[junit4] 2> 21500 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-map-failure
[junit4] 2> 21502 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-map-running
[junit4] 2> 21503 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-map-completed
[junit4] 2> 21504 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-queue-work
[junit4] 2> 21507 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.OverseerAutoReplicaFailoverThread Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 21507 INFO (OverseerCollectionConfigSetProcessor-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskProcessor Process current queue of overseer operations
[junit4] 2> 21507 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.Overseer Starting to work on the main queue
[junit4] 2> 21508 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 21510 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"} current state version: 0
[junit4] 2> 21511 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 21511 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.o.ClusterStateMutator building a new cName: collection1
[junit4] 2> 21511 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 21512 INFO (zkCallback-24-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 21512 INFO (zkCallback-27-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 21512 INFO (zkCallback-28-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 22009 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 22010 INFO (zkCallback-27-thread-1) [ ] o.a.s.c.c.ZkStateReader A collections change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/collections, has occurred - updating...
[junit4] 2> 22010 INFO (zkCallback-24-thread-1) [ ] o.a.s.c.c.ZkStateReader A collections change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/collections, has occurred - updating...
[junit4] 2> 22011 INFO (zkCallback-28-thread-1) [ ] o.a.s.c.c.ZkStateReader A collections change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/collections, has occurred - updating...
[junit4] 2> 22013 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /collections/collection1/leader_elect/shard1/election/94820355749249027-node1_core1-n_0000000000
[junit4] 2> 22013 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/leaders/shard1
[junit4] 2> 22014 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ShardLeaderElectionContextBase Creating leader registration node
[junit4] 2> 22016 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "base_url":"http://node1/solr/",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "core":"core1"} current state version: 1
[junit4] 2> 22016 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "base_url":"http://node1/solr/",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "core":"core1"}
[junit4] 2> 22018 INFO (zkCallback-24-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 22017 INFO (zkCallback-28-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 22017 INFO (zkCallback-27-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 22027 WARN (zkCallback-27-thread-1) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 22028 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 22028 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 22029 INFO (zkCallback-30-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@9855fe name:ZooKeeperConnection Watcher:127.0.0.1:36447/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 22029 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 22029 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 22030 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"leader",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "base_url":"http://node1/solr/",
[junit4] 2> "core":"core1"} current state version: 1
[junit4] 2> 22030 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 22032 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /live_nodes/node1
[junit4] 2> 22033 INFO (zkCallback-28-thread-2) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 0)
[junit4] 2> 22034 INFO (zkCallback-24-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 0)
[junit4] 2> 22034 INFO (zkCallback-30-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 0)
[junit4] 2> 22034 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 22034 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"} current state version: 1
[junit4] 2> 22035 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 22035 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator shard=shard1 is already registered
[junit4] 2> 22036 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /collections/collection1/leader_elect/shard1/election/94820355749249029-node1_core1-n_0000000001
[junit4] 2> 22037 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ShardLeaderElectionContextBase Creating leader registration node
[junit4] 2> 22038 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "base_url":"http://node1/solr/",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "core":"core1"} current state version: 1
[junit4] 2> 22038 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "base_url":"http://node1/solr/",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "core":"core1"}
[junit4] 2> 22040 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"leader",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "base_url":"http://node1/solr/",
[junit4] 2> "core":"core1"} current state version: 1
[junit4] 2> 22147 INFO (zkCallback-24-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 22147 INFO (zkCallback-28-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 22148 INFO (zkCallback-30-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 22149 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x150de9c75e90004, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 22150 INFO (zkCallback-30-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 22150 INFO (zkCallback-24-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 23510 INFO (OverseerCollectionConfigSetProcessor-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskProcessor
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:345)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:61)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor.amILeader(OverseerTaskProcessor.java:355)
[junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor.run(OverseerTaskProcessor.java:172)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 23510 INFO (OverseerCollectionConfigSetProcessor-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskProcessor According to ZK I (id=94820355749249028-127.0.0.1:36447_solr-n_0000000000) am no longer a leader.
[junit4] 2> 23649 WARN (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.Overseer Solr cannot talk to ZK, exiting Overseer main queue loop
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer/queue-work/qn-0000000001
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:244)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:241)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:61)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:241)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.removeFirst(DistributedQueue.java:386)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.poll(DistributedQueue.java:188)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:239)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 23649 INFO (OverseerStateUpdate-94820355749249028-127.0.0.1:36447_solr-n_0000000000) [ ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:36447_solr
[junit4] 2> 23649 ERROR (OverseerExitThread) [ ] o.a.s.c.Overseer could not read the data
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:345)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:61)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:87)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$2.run(Overseer.java:265)
[junit4] 2> 23650 WARN (zkCallback-30-thread-1) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 23651 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:36447 36447
[junit4] 2> 23657 INFO (Thread-123) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:36447 36447
[junit4] 2> 23657 WARN (Thread-123) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 4 /solr/aliases.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 4 /solr/clusterstate.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 4 /solr/collections
[junit4] 2> 3 /solr/live_nodes
[junit4] 2>
[junit4] 2> 23657 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDoubleAssignment
[junit4] 2> 23657 INFO (TEST-OverseerTest.testDoubleAssignment-seed#[33AD9326861AACB1]) [ ] o.a.s.c.Overseer Overseer (id=94820355749249028-127.0.0.1:36447_solr-n_0000000000) closing
[junit4] 2> 23660 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testShardLeaderChange
[junit4] 2> 23660 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 23660 INFO (Thread-124) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 23660 INFO (Thread-124) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 23760 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ZkTestServer start zk server on port:47949
[junit4] 2> 23760 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 23761 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 23762 INFO (zkCallback-31-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@c361fe name:ZooKeeperConnection Watcher:127.0.0.1:47949/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 23762 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 23763 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 23763 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 23763 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 23764 INFO (zkCallback-32-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@1191e66 name:ZooKeeperConnection Watcher:127.0.0.1:47949 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 23764 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 23764 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 23765 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 23765 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 23766 INFO (zkCallback-33-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@2be961 name:ZooKeeperConnection Watcher:127.0.0.1:47949 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 23766 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 23766 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 23766 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /solr
[junit4] 2> 23768 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /live_nodes
[junit4] 2> 23769 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections
[junit4] 2> 23769 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /aliases.json
[junit4] 2> 23770 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /clusterstate.json
[junit4] 2> 23770 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /security.json
[junit4] 2> 23772 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 23772 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 23772 INFO (Thread-125) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 23772 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 23773 INFO (zkCallback-35-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@f35e2b name:ZooKeeperConnection Watcher:127.0.0.1:47949/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 23773 INFO (Thread-125) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 23773 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@1d4342f name:ZooKeeperConnection Watcher:127.0.0.1:47949/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 23773 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 23773 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 23773 INFO (Thread-125) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=600000&connTimeout=60000&retry=true
[junit4] 2> 23773 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 23774 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer_elect
[junit4] 2> 23774 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 23775 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer_elect/election
[junit4] 2> 23776 INFO (Thread-125) [ ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 23776 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /live_nodes/node1
[junit4] 2> 23776 INFO (Thread-125) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /overseer_elect/election/94820355901816835-127.0.0.1:47949_solr-n_0000000000
[junit4] 2> 23776 INFO (Thread-125) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:47949_solr
[junit4] 2> 23776 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer_elect/leader
[junit4] 2> 23777 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 0)
[junit4] 2> 23777 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/queue
[junit4] 2> 23777 INFO (Thread-125) [ ] o.a.s.c.Overseer Overseer (id=94820355901816835-127.0.0.1:47949_solr-n_0000000000) starting
[junit4] 2> 23778 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/queue-work
[junit4] 2> 23779 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-map-failure
[junit4] 2> 23780 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-map-running
[junit4] 2> 23781 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-map-completed
[junit4] 2> 23782 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer/collection-queue-work
[junit4] 2> 23783 INFO (Thread-125) [ ] o.a.s.c.OverseerAutoReplicaFailoverThread Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 23784 INFO (OverseerCollectionConfigSetProcessor-94820355901816835-127.0.0.1:47949_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskProcessor Process current queue of overseer operations
[junit4] 2> 23784 INFO (Thread-125) [ ] o.a.s.SolrTestCaseJ4 Killing overseer.
[junit4] 2> 23784 INFO (OverseerStateUpdate-94820355901816835-127.0.0.1:47949_solr-n_0000000000) [ ] o.a.s.c.Overseer Starting to work on the main queue
[junit4] 2> 23784 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 23785 INFO (Thread-125) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 23786 INFO (zkCallback-37-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@f50c96 name:ZooKeeperConnection Watcher:127.0.0.1:47949/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 23786 INFO (Thread-125) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 23786 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 23786 INFO (Thread-125) [ ] o.a.s.c.Overseer Overseer (id=94820355901816835-127.0.0.1:47949_solr-n_0000000000) closing
[junit4] 2> 23786 INFO (Thread-125) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=600000&connTimeout=60000&retry=true
[junit4] 2> 23786 INFO (OverseerStateUpdate-94820355901816835-127.0.0.1:47949_solr-n_0000000000) [ ] o.a.s.c.Overseer According to ZK I (id=94820355901816835-127.0.0.1:47949_solr-n_0000000000) am no longer a leader.
[junit4] 2> 23786 ERROR (OverseerCollectionConfigSetProcessor-94820355901816835-127.0.0.1:47949_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskProcessor Unable to prioritize overseer
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /roles.json
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:1045)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$5.execute(SolrZkClient.java:311)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$5.execute(SolrZkClient.java:308)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:61)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.exists(SolrZkClient.java:308)
[junit4] 2> at org.apache.solr.cloud.OverseerNodePrioritizer.prioritizeOverseerNodes(OverseerNodePrioritizer.java:59)
[junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor.run(OverseerTaskProcessor.java:159)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 23786 INFO (OverseerStateUpdate-94820355901816835-127.0.0.1:47949_solr-n_0000000000) [ ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:47949_solr
[junit4] 2> 23787 ERROR (OverseerExitThread) [ ] o.a.s.c.Overseer could not read the data
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:345)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:61)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:87)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$2.run(Overseer.java:265)
[junit4] 2> 23788 INFO (Thread-125) [ ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 23788 INFO (Thread-125) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /overseer_elect/election/94820355901816837-127.0.0.1:47949_solr-n_0000000001
[junit4] 2> 23788 INFO (Thread-125) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:47949_solr
[junit4] 2> 23788 INFO (Thread-125) [ ] o.a.s.c.c.SolrZkClient makePath: /overseer_elect/leader
[junit4] 2> 23789 INFO (Thread-125) [ ] o.a.s.c.Overseer Overseer (id=94820355901816837-127.0.0.1:47949_solr-n_0000000001) starting
[junit4] 2> 23794 INFO (Thread-125) [ ] o.a.s.c.OverseerAutoReplicaFailoverThread Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 23794 INFO (OverseerCollectionConfigSetProcessor-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.OverseerTaskProcessor Process current queue of overseer operations
[junit4] 2> 23795 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.Overseer Starting to work on the main queue
[junit4] 2> 23795 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 23796 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"} current state version: 0
[junit4] 2> 23797 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 23797 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ClusterStateMutator building a new cName: collection1
[junit4] 2> 23797 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 23797 INFO (zkCallback-37-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 23797 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 24278 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 24279 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ZkStateReader A collections change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/collections, has occurred - updating...
[junit4] 2> 24279 INFO (zkCallback-37-thread-1) [ ] o.a.s.c.c.ZkStateReader A collections change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/collections, has occurred - updating...
[junit4] 2> 24282 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /collections/collection1/leader_elect/shard1/election/94820355901816836-node1_core1-n_0000000000
[junit4] 2> 24282 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/leaders/shard1
[junit4] 2> 24283 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ShardLeaderElectionContextBase Creating leader registration node
[junit4] 2> 24286 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"leader",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "base_url":"http://node1/solr/",
[junit4] 2> "core":"core1"} current state version: 1
[junit4] 2> 24287 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 24288 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"} current state version: 1
[junit4] 2> 24288 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 24288 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ReplicaMutator shard=shard1 is already registered
[junit4] 2> 24289 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /collections/collection1/leader_elect/shard1/election/94820355901816836-node1_core1-n_0000000001
[junit4] 2> 24290 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector was going to be leader /collections/collection1/leader_elect/shard1/election/94820355901816836-node1_core1-n_0000000001 , seq(0) /collections/collection1/leader_elect/shard1/election/94820355901816836-node1_core1-n_0000000000
[junit4] 2> 24290 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 24290 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 24292 INFO (zkCallback-39-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@e8caa0 name:ZooKeeperConnection Watcher:127.0.0.1:47949/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 24292 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 24292 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 24293 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 24294 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /live_nodes/node2
[junit4] 2> 24296 INFO (zkCallback-39-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 24296 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 24296 INFO (zkCallback-37-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 24297 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 24298 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"} current state version: 1
[junit4] 2> 24298 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 24298 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ReplicaMutator shard=shard1 is already registered
[junit4] 2> 24299 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /collections/collection1/leader_elect/shard1/election/94820355901816836-node1_core1-n_0000000002
[junit4] 2> 24299 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector was going to be leader /collections/collection1/leader_elect/shard1/election/94820355901816836-node1_core1-n_0000000002 , seq(0) /collections/collection1/leader_elect/shard1/election/94820355901816836-node1_core1-n_0000000000
[junit4] 2> 24299 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 24400 INFO (zkCallback-39-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 24400 INFO (zkCallback-31-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 24400 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 24402 INFO (zkCallback-37-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 24503 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"node2",
[junit4] 2> "core":"core4",
[junit4] 2> "core_node_name":"node2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node2/solr/"} current state version: 2
[junit4] 2> 24503 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"node2",
[junit4] 2> "core":"core4",
[junit4] 2> "core_node_name":"node2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node2/solr/"}
[junit4] 2> 24503 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ReplicaMutator Collection already exists with numShards=1
[junit4] 2> 24503 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 24605 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 24605 INFO (zkCallback-37-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 24605 INFO (zkCallback-39-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 24605 INFO (zkCallback-31-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 25002 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 25005 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /collections/collection1/leader_elect/shard1/election/94820355901816838-node2_core4-n_0000000003
[junit4] 2> 25007 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Watching path /collections/collection1/leader_elect/shard1/election/94820355901816836-node1_core1-n_0000000002 to know if I could be the leader
[junit4] 2> 25008 INFO (zkCallback-37-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 25008 INFO (zkCallback-31-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 25008 INFO (zkCallback-34-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 25009 INFO (zkCallback-39-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 25012 INFO (zkCallback-39-thread-2) [ ] o.a.s.c.ShardLeaderElectionContextBase Creating leader registration node
[junit4] 2> 25014 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"leader",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "base_url":"http://node2/solr/",
[junit4] 2> "core":"core4"} current state version: 3
[junit4] 2> 25116 INFO (zkCallback-37-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 25116 INFO (zkCallback-39-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 25116 INFO (zkCallback-31-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 25212 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkCredentialsProvider
[junit4] 2> 25212 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Waiting for client to connect to ZooKeeper
[junit4] 2> 25213 INFO (zkCallback-40-thread-1) [ ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@4f7a1b name:ZooKeeperConnection Watcher:127.0.0.1:47949/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 25213 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 25214 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient Using default ZkACLProvider
[junit4] 2> 25215 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 25216 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /live_nodes/node1
[junit4] 2> 25217 INFO (zkCallback-39-thread-2) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 25217 INFO (zkCallback-37-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 25217 INFO (zkCallback-31-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 25217 INFO (zkCallback-40-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4] 2> 25218 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.c.SolrZkClient makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 25218 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"} current state version: 4
[junit4] 2> 25219 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 25219 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_0000000001) [ ] o.a.s.c.o.ReplicaMutator shard=shard1 is already registered
[junit4] 2> 25220 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Joined leadership election with path: /collections/collection1/leader_elect/shard1/election/94820355901816839-node1_core1-n_0000000004
[junit4] 2> 25221 INFO (TEST-OverseerTest.testShardLeaderChange-seed#[33AD9326861AACB1]) [ ] o.a.s.c.LeaderElector Watching path /collections/collection1/leader_elect/shard1/election/94820355901816838-node2_core4-n_0000000003 to know if I could be the leader
[junit4] 2> 25221 INFO (zkCallback-39-thread-2) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 25221 INFO (zkCallback-37-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 25221 INFO (zkCallback-31-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 25223 INFO (zkCallback-40-thread-1) [ ] o.a.s.c.c.ZkStateReader A live node change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4] 2> 25224 INFO (zkCallback-40-thread-2) [ ] o.a.s.c.ShardLeaderElectionContextBase Creating leader registration node
[junit4] 2> 25226 INFO (OverseerStateUpdate-94820355901816837-127.0.0.1:47949_solr-n_000000000
[...truncated too long message...]
Replay-seed#[33AD9326861AACB1]) [ ] o.a.s.c.OverseerAutoReplicaFailoverThread Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 86090 INFO (OverseerCollectionConfigSetProcessor-94820359985168387-127.0.0.1:57122_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskProcessor Process current queue of overseer operations
[junit4] 2> 86091 INFO (OverseerStateUpdate-94820359985168387-127.0.0.1:57122_solr-n_0000000000) [ ] o.a.s.c.Overseer Starting to work on the main queue
[junit4] 2> 86091 INFO (OverseerStateUpdate-94820359985168387-127.0.0.1:57122_solr-n_0000000000) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 86098 INFO (OverseerStateUpdate-94820359985168387-127.0.0.1:57122_solr-n_0000000000) [ ] o.a.s.c.Overseer processMessage: workQueueSize: 2, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "shard":"s1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core1",
[junit4] 2> "roles":"",
[junit4] 2> "state":"recovering"}
[junit4] 2> 86098 INFO (OverseerStateUpdate-94820359985168387-127.0.0.1:57122_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "shard":"s1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core1",
[junit4] 2> "roles":"",
[junit4] 2> "state":"recovering"}
[junit4] 2> 86099 INFO (zkCallback-156-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 86099 INFO (zkCallback-153-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 86100 INFO (OverseerStateUpdate-94820359985168387-127.0.0.1:57122_solr-n_0000000000) [ ] o.a.s.c.Overseer processMessage: workQueueSize: 2, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "shard":"s1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core2",
[junit4] 2> "roles":"",
[junit4] 2> "state":"recovering"}
[junit4] 2> 86100 INFO (OverseerStateUpdate-94820359985168387-127.0.0.1:57122_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "shard":"s1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core2",
[junit4] 2> "roles":"",
[junit4] 2> "state":"recovering"}
[junit4] 2> 86100 INFO (zkCallback-156-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 86100 INFO (zkCallback-153-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 86101 INFO (OverseerStateUpdate-94820359985168387-127.0.0.1:57122_solr-n_0000000000) [ ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "shard":"s1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core3",
[junit4] 2> "roles":"",
[junit4] 2> "state":"recovering"} current state version: 2
[junit4] 2> 86101 INFO (OverseerStateUpdate-94820359985168387-127.0.0.1:57122_solr-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "shard":"s1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core3",
[junit4] 2> "roles":"",
[junit4] 2> "state":"recovering"}
[junit4] 2> 86203 INFO (zkCallback-156-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 86203 INFO (zkCallback-153-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 86293 INFO (TEST-OverseerTest.testReplay-seed#[33AD9326861AACB1]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:57122 57122
[junit4] 2> 86404 INFO (Thread-133) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:57122 57122
[junit4] 2> 86405 WARN (Thread-133) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 2 /solr/aliases.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 2 /solr/clusterstate.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 2 /solr/live_nodes
[junit4] 2> 2 /solr/collections
[junit4] 2>
[junit4] 2> 86405 INFO (TEST-OverseerTest.testReplay-seed#[33AD9326861AACB1]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testReplay
[junit4] 2> 86405 INFO (TEST-OverseerTest.testReplay-seed#[33AD9326861AACB1]) [ ] o.a.s.c.Overseer Overseer (id=94820359985168387-127.0.0.1:57122_solr-n_0000000000) closing
[junit4] 2> 86405 INFO (OverseerStateUpdate-94820359985168387-127.0.0.1:57122_solr-n_0000000000) [ ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:57122_solr
[junit4] 2> 86405 ERROR (OverseerExitThread) [ ] o.a.s.c.Overseer could not read the data
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:345)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:61)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:87)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$2.run(Overseer.java:265)
[junit4] 2> 89406 INFO (SUITE-OverseerTest-seed#[33AD9326861AACB1]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-5.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.OverseerTest_33AD9326861AACB1-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene54): {}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=th, timezone=America/Cambridge_Bay
[junit4] 2> NOTE: Linux 3.19.0-31-generic i386/Oracle Corporation 1.8.0_66 (32-bit)/cpus=12,threads=1,free=23979504,total=72699904
[junit4] 2> NOTE: All tests run in this JVM: [TestRandomMergePolicy, HdfsChaosMonkeyNothingIsSafeTest, TestCollationField, HdfsSyncSliceTest, TestCSVResponseWriter, TestImplicitCoreProperties, TestConfigSetImmutable, TestComplexPhraseQParserPlugin, CircularListTest, TestConfigSetsAPIExclusivity, TestReload, OverseerTest]
[junit4] Completed [35/545] on J2 in 70.38s, 12 tests, 1 failure, 1 skipped <<< FAILURES!
[...truncated 1596 lines...]
BUILD FAILED
/home/jenkins/workspace/Lucene-Solr-5.x-Linux/build.xml:785: The following error occurred while executing this line:
/home/jenkins/workspace/Lucene-Solr-5.x-Linux/build.xml:729: The following error occurred while executing this line:
/home/jenkins/workspace/Lucene-Solr-5.x-Linux/build.xml:59: The following error occurred while executing this line:
/home/jenkins/workspace/Lucene-Solr-5.x-Linux/solr/build.xml:233: The following error occurred while executing this line:
/home/jenkins/workspace/Lucene-Solr-5.x-Linux/solr/common-build.xml:526: The following error occurred while executing this line:
/home/jenkins/workspace/Lucene-Solr-5.x-Linux/lucene/common-build.xml:1452: The following error occurred while executing this line:
/home/jenkins/workspace/Lucene-Solr-5.x-Linux/lucene/common-build.xml:1006: There were test failures: 545 suites (7 ignored), 2158 tests, 1 failure, 75 ignored (37 assumptions) [seed: 33AD9326861AACB1]
Total time: 54 minutes 14 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
[WARNINGS] Skipping publisher since build result is FAILURE
Recording test results
Email was triggered for: Failure - Any
Sending email for trigger: Failure - Any