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 2017/01/26 21:14:05 UTC
[JENKINS-EA] Lucene-Solr-6.4-Linux (32bit/jdk-9-ea+153) - Build #
55 - Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.4-Linux/55/
Java: 32bit/jdk-9-ea+153 -server -XX:+UseSerialGC
1 tests failed.
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.CollectionsAPISolrJTest
Error Message:
1 thread leaked from SUITE scope at org.apache.solr.cloud.CollectionsAPISolrJTest: 1) Thread[id=2941, name=OverseerHdfsCoreFailoverThread-97351290866171910-127.0.0.1:42762_solr-n_0000000004, state=TIMED_WAITING, group=Overseer Hdfs SolrCore Failover Thread.] at java.base@9-ea/java.lang.Thread.sleep(Native Method) at app//org.apache.solr.cloud.OverseerAutoReplicaFailoverThread.run(OverseerAutoReplicaFailoverThread.java:139) at java.base@9-ea/java.lang.Thread.run(Thread.java:844)
Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.CollectionsAPISolrJTest:
1) Thread[id=2941, name=OverseerHdfsCoreFailoverThread-97351290866171910-127.0.0.1:42762_solr-n_0000000004, state=TIMED_WAITING, group=Overseer Hdfs SolrCore Failover Thread.]
at java.base@9-ea/java.lang.Thread.sleep(Native Method)
at app//org.apache.solr.cloud.OverseerAutoReplicaFailoverThread.run(OverseerAutoReplicaFailoverThread.java:139)
at java.base@9-ea/java.lang.Thread.run(Thread.java:844)
at __randomizedtesting.SeedInfo.seed([157992962A846398]:0)
Build Log:
[...truncated 11179 lines...]
[junit4] Suite: org.apache.solr.cloud.CollectionsAPISolrJTest
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/init-core-data-001
[junit4] 2> 443053 INFO (SUITE-CollectionsAPISolrJTest-seed#[157992962A846398]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason="", ssl=0.0/0.0, value=0.0/0.0, clientAuth=0.0/0.0)
[junit4] 2> 443054 INFO (SUITE-CollectionsAPISolrJTest-seed#[157992962A846398]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 4 servers in /home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001
[junit4] 2> 443054 INFO (SUITE-CollectionsAPISolrJTest-seed#[157992962A846398]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 443055 INFO (Thread-536) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 443055 INFO (Thread-536) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 443155 INFO (SUITE-CollectionsAPISolrJTest-seed#[157992962A846398]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:46718
[junit4] 2> 443159 INFO (jetty-launcher-533-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 443159 INFO (jetty-launcher-533-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 443160 INFO (jetty-launcher-533-thread-3) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 443160 INFO (jetty-launcher-533-thread-4) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 443168 INFO (jetty-launcher-533-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@10e4d7f{/solr,null,AVAILABLE}
[junit4] 2> 443168 INFO (jetty-launcher-533-thread-4) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1bee377{/solr,null,AVAILABLE}
[junit4] 2> 443168 INFO (jetty-launcher-533-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@35dfc7{/solr,null,AVAILABLE}
[junit4] 2> 443168 INFO (jetty-launcher-533-thread-3) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1866ca4{/solr,null,AVAILABLE}
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@b0a8db{HTTP/1.1,[http/1.1]}{127.0.0.1:٣٦٢٢٥}
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-4) [ ] o.e.j.s.AbstractConnector Started ServerConnector@47aa00{HTTP/1.1,[http/1.1]}{127.0.0.1:٣٩٦٨٦}
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-1) [ ] o.e.j.s.Server Started @٤٤٤٩٢٢ms
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-4) [ ] o.e.j.s.Server Started @٤٤٤٩٢٢ms
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=36225}
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-4) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=39686}
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1de14f9{HTTP/1.1,[http/1.1]}{127.0.0.1:٣٧٢٠٦}
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-3) [ ] o.e.j.s.AbstractConnector Started ServerConnector@989b11{HTTP/1.1,[http/1.1]}{127.0.0.1:٤٢٧٦٢}
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-2) [ ] o.e.j.s.Server Started @٤٤٤٩٢٢ms
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-3) [ ] o.e.j.s.Server Started @٤٤٤٩٢٣ms
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=37206}
[junit4] 2> 443170 ERROR (jetty-launcher-533-thread-4) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=42762}
[junit4] 2> 443170 ERROR (jetty-launcher-533-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-4) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.1
[junit4] 2> 443170 ERROR (jetty-launcher-533-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-4) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 443170 ERROR (jetty-launcher-533-thread-3) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.1
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.1
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-4) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.1
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-4) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-01-26T20:33:32.402718Z
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-01-26T20:33:32.402738Z
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-01-26T20:33:32.402856Z
[junit4] 2> 443170 INFO (jetty-launcher-533-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-01-26T20:33:32.402905Z
[junit4] 2> 443185 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 443185 INFO (jetty-launcher-533-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 443185 INFO (jetty-launcher-533-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 443185 INFO (jetty-launcher-533-thread-4) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 443188 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 0x159dc7bb6810004, 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.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2> 443188 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 0x159dc7bb6810003, 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.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2> 443190 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 443192 INFO (jetty-launcher-533-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 443193 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:46718/solr
[junit4] 2> 443197 INFO (jetty-launcher-533-thread-2) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 443199 INFO (jetty-launcher-533-thread-4) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 443201 INFO (jetty-launcher-533-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:46718/solr
[junit4] 2> 443203 INFO (jetty-launcher-533-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:46718/solr
[junit4] 2> 443204 INFO (jetty-launcher-533-thread-4) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:46718/solr
[junit4] 2> 443206 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:42762_solr
[junit4] 2> 443207 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.c.Overseer Overseer (id=97351290866171910-127.0.0.1:42762_solr-n_0000000000) starting
[junit4] 2> 443211 INFO (jetty-launcher-533-thread-2) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37206_solr
[junit4] 2> 443212 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 443212 INFO (zkCallback-544-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 443213 INFO (zkCallback-553-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 443213 INFO (jetty-launcher-533-thread-4) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 443213 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42762_solr
[junit4] 2> 443214 INFO (jetty-launcher-533-thread-1) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36225_solr
[junit4] 2> 443214 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 443214 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 443214 INFO (zkCallback-553-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 443214 INFO (zkCallback-544-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 443215 INFO (zkCallback-544-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 443215 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 443215 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 443215 INFO (zkCallback-553-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 443216 INFO (jetty-launcher-533-thread-4) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39686_solr
[junit4] 2> 443216 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 443216 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 443216 INFO (zkCallback-544-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 443216 INFO (zkCallback-553-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 443263 INFO (jetty-launcher-533-thread-4) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node4/.
[junit4] 2> 443275 INFO (jetty-launcher-533-thread-2) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node2/.
[junit4] 2> 443277 INFO (jetty-launcher-533-thread-3) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node3/.
[junit4] 2> 443352 INFO (jetty-launcher-533-thread-1) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node1/.
[junit4] 2> 444080 INFO (SUITE-CollectionsAPISolrJTest-seed#[157992962A846398]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 444081 INFO (SUITE-CollectionsAPISolrJTest-seed#[157992962A846398]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:46718/solr ready
[junit4] 2> 444117 INFO (TEST-CollectionsAPISolrJTest.testClusterProp-seed#[157992962A846398]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testClusterProp
[junit4] 2> 444122 INFO (qtp17956584-2681) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :clusterprop with params val=false&name=legacyCloud&action=CLUSTERPROP&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 444124 INFO (qtp17956584-2681) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={val=false&name=legacyCloud&action=CLUSTERPROP&wt=javabin&version=2} status=0 QTime=1
[junit4] 2> 444126 INFO (qtp17956584-2684) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :clusterprop with params name=legacyCloud&action=CLUSTERPROP&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 444127 INFO (qtp17956584-2684) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=legacyCloud&action=CLUSTERPROP&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 444127 INFO (TEST-CollectionsAPISolrJTest.testClusterProp-seed#[157992962A846398]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testClusterProp
[junit4] 2> 444147 INFO (TEST-CollectionsAPISolrJTest.testCreateAndDeleteAlias-seed#[157992962A846398]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateAndDeleteAlias
[junit4] 2> 444149 INFO (qtp17956584-2688) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf&name=aliasedCollection&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 444151 INFO (OverseerThreadFactory-1246-thread-1) [ ] o.a.s.c.CreateCollectionCmd Create collection aliasedCollection
[junit4] 2> 444256 INFO (qtp15952999-2678) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=aliasedCollection_shard1_replica1&action=CREATE&numShards=1&collection=aliasedCollection&shard=shard1&wt=javabin&version=2
[junit4] 2> 444360 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/aliasedCollection/state.json] for collection [aliasedCollection] has occurred - updating... (live nodes size: [4])
[junit4] 2> 445273 INFO (qtp15952999-2678) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.1
[junit4] 2> 445292 INFO (qtp15952999-2678) [ ] o.a.s.s.IndexSchema [aliasedCollection_shard1_replica1] Schema name=minimal
[junit4] 2> 445305 INFO (qtp15952999-2678) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 445306 INFO (qtp15952999-2678) [ ] o.a.s.c.CoreContainer Creating SolrCore 'aliasedCollection_shard1_replica1' using configuration from collection aliasedCollection
[junit4] 2> 445307 INFO (qtp15952999-2678) [ ] o.a.s.c.SolrCore [[aliasedCollection_shard1_replica1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node4/aliasedCollection_shard1_replica1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node4/./aliasedCollection_shard1_replica1/data/]
[junit4] 2> 445326 INFO (qtp15952999-2678) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 445326 INFO (qtp15952999-2678) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 445333 INFO (qtp15952999-2678) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 445333 INFO (qtp15952999-2678) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 445335 INFO (qtp15952999-2678) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@153719[aliasedCollection_shard1_replica1] main]
[junit4] 2> 445335 INFO (qtp15952999-2678) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 445335 INFO (qtp15952999-2678) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 445335 INFO (qtp15952999-2678) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 445336 INFO (searcherExecutor-1255-thread-1) [ ] o.a.s.c.SolrCore [aliasedCollection_shard1_replica1] Registered new searcher Searcher@153719[aliasedCollection_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 445336 INFO (qtp15952999-2678) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1557620656248455168
[junit4] 2> 445349 INFO (qtp15952999-2678) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 445349 INFO (qtp15952999-2678) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 445349 INFO (qtp15952999-2678) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:39686/solr/aliasedCollection_shard1_replica1/
[junit4] 2> 445349 INFO (qtp15952999-2678) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 445349 INFO (qtp15952999-2678) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:39686/solr/aliasedCollection_shard1_replica1/ has no replicas
[junit4] 2> 445352 INFO (qtp15952999-2678) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:39686/solr/aliasedCollection_shard1_replica1/ shard1
[junit4] 2> 445453 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/aliasedCollection/state.json] for collection [aliasedCollection] has occurred - updating... (live nodes size: [4])
[junit4] 2> 445502 INFO (qtp15952999-2678) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 445507 INFO (qtp15952999-2678) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=aliasedCollection_shard1_replica1&action=CREATE&numShards=1&collection=aliasedCollection&shard=shard1&wt=javabin&version=2} status=0 QTime=1251
[junit4] 2> 445509 INFO (qtp17956584-2688) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
[junit4] 2> 445605 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/aliasedCollection/state.json] for collection [aliasedCollection] has occurred - updating... (live nodes size: [4])
[junit4] 2> 446152 INFO (OverseerCollectionConfigSetProcessor-97351290866171910-127.0.0.1:42762_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 446510 INFO (qtp17956584-2688) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf&name=aliasedCollection&action=CREATE&numShards=1&wt=javabin&version=2} status=0 QTime=2360
[junit4] 2> 446513 INFO (qtp17956584-2662) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :createalias with params collections=aliasedCollection&name=solrj_alias&action=CREATEALIAS&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 446615 INFO (qtp17956584-2662) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={collections=aliasedCollection&name=solrj_alias&action=CREATEALIAS&wt=javabin&version=2} status=0 QTime=102
[junit4] 2> 446618 INFO (qtp17956584-2681) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :deletealias with params name=solrj_alias&action=DELETEALIAS&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 446619 INFO (OverseerCollectionConfigSetProcessor-97351290866171910-127.0.0.1:42762_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000002 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 446720 INFO (qtp17956584-2681) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=solrj_alias&action=DELETEALIAS&wt=javabin&version=2} status=0 QTime=102
[junit4] 2> 446721 INFO (TEST-CollectionsAPISolrJTest.testCreateAndDeleteAlias-seed#[157992962A846398]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreateAndDeleteAlias
[junit4] 2> 446739 INFO (TEST-CollectionsAPISolrJTest.testCreateCollectionWithPropertyParam-seed#[157992962A846398]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateCollectionWithPropertyParam
[junit4] 2> 446742 INFO (qtp17956584-2684) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&property.ulogDir=/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/testPropertyParamsForCreate-001/ulogDir-gptdv&property.dataDir=/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/testPropertyParamsForCreate-001/dataDir-ml&collection.configName=conf&name=solrj_test_core_props&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 446743 INFO (OverseerThreadFactory-1246-thread-4) [ ] o.a.s.c.CreateCollectionCmd Create collection solrj_test_core_props
[junit4] 2> 446744 INFO (OverseerCollectionConfigSetProcessor-97351290866171910-127.0.0.1:42762_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000004 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 446947 INFO (qtp17956584-2662) [ ] o.a.s.h.a.CoreAdminOperation core create command property.ulogDir=/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/testPropertyParamsForCreate-001/ulogDir-gptdv&qt=/admin/cores&property.dataDir=/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/testPropertyParamsForCreate-001/dataDir-ml&collection.configName=conf&newCollection=true&name=solrj_test_core_props_shard1_replica1&action=CREATE&numShards=1&collection=solrj_test_core_props&shard=shard1&wt=javabin&version=2
[junit4] 2> 447051 INFO (zkCallback-553-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_test_core_props/state.json] for collection [solrj_test_core_props] has occurred - updating... (live nodes size: [4])
[junit4] 2> 447957 INFO (qtp17956584-2662) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.1
[junit4] 2> 447964 INFO (qtp17956584-2662) [ ] o.a.s.s.IndexSchema [solrj_test_core_props_shard1_replica1] Schema name=minimal
[junit4] 2> 447982 INFO (qtp17956584-2662) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 447983 INFO (qtp17956584-2662) [ ] o.a.s.c.CoreContainer Creating SolrCore 'solrj_test_core_props_shard1_replica1' using configuration from collection solrj_test_core_props
[junit4] 2> 447983 INFO (qtp17956584-2662) [ ] o.a.s.c.SolrCore [[solrj_test_core_props_shard1_replica1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node1/solrj_test_core_props_shard1_replica1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/testPropertyParamsForCreate-001/dataDir-ml/]
[junit4] 2> 448004 INFO (qtp17956584-2662) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 448004 INFO (qtp17956584-2662) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 448010 INFO (qtp17956584-2662) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 448010 INFO (qtp17956584-2662) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 448011 INFO (qtp17956584-2662) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@704790[solrj_test_core_props_shard1_replica1] main]
[junit4] 2> 448012 INFO (qtp17956584-2662) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 448012 INFO (qtp17956584-2662) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 448012 INFO (qtp17956584-2662) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 448012 INFO (searcherExecutor-1260-thread-1) [ ] o.a.s.c.SolrCore [solrj_test_core_props_shard1_replica1] Registered new searcher Searcher@704790[solrj_test_core_props_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 448012 INFO (qtp17956584-2662) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1557620659054444544
[junit4] 2> 448017 INFO (qtp17956584-2662) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 448017 INFO (qtp17956584-2662) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 448017 INFO (qtp17956584-2662) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:36225/solr/solrj_test_core_props_shard1_replica1/
[junit4] 2> 448017 INFO (qtp17956584-2662) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 448017 INFO (qtp17956584-2662) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:36225/solr/solrj_test_core_props_shard1_replica1/ has no replicas
[junit4] 2> 448019 INFO (qtp17956584-2662) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:36225/solr/solrj_test_core_props_shard1_replica1/ shard1
[junit4] 2> 448121 INFO (zkCallback-553-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_test_core_props/state.json] for collection [solrj_test_core_props] has occurred - updating... (live nodes size: [4])
[junit4] 2> 448169 INFO (qtp17956584-2662) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 448172 INFO (qtp17956584-2662) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={property.ulogDir=/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/testPropertyParamsForCreate-001/ulogDir-gptdv&qt=/admin/cores&property.dataDir=/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/testPropertyParamsForCreate-001/dataDir-ml&collection.configName=conf&newCollection=true&name=solrj_test_core_props_shard1_replica1&action=CREATE&numShards=1&collection=solrj_test_core_props&shard=shard1&wt=javabin&version=2} status=0 QTime=1224
[junit4] 2> 448173 INFO (qtp17956584-2684) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
[junit4] 2> 448272 INFO (zkCallback-553-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_test_core_props/state.json] for collection [solrj_test_core_props] has occurred - updating... (live nodes size: [4])
[junit4] 2> 448745 INFO (OverseerCollectionConfigSetProcessor-97351290866171910-127.0.0.1:42762_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000006 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 449173 INFO (qtp17956584-2684) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&property.ulogDir=/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/testPropertyParamsForCreate-001/ulogDir-gptdv&property.dataDir=/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/testPropertyParamsForCreate-001/dataDir-ml&collection.configName=conf&name=solrj_test_core_props&action=CREATE&numShards=1&wt=javabin&version=2} status=0 QTime=2431
[junit4] 2> 449177 INFO (qtp17956584-2688) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={action=STATUS&indexInfo=true&wt=javabin&version=2} status=0 QTime=1
[junit4] 2> 449177 INFO (TEST-CollectionsAPISolrJTest.testCreateCollectionWithPropertyParam-seed#[157992962A846398]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreateCollectionWithPropertyParam
[junit4] 2> 449196 INFO (TEST-CollectionsAPISolrJTest.testAddAndDeleteReplica-seed#[157992962A846398]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testAddAndDeleteReplica
[junit4] 2> 449197 INFO (qtp17956584-2666) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=2&collection.configName=conf&name=solrj_replicatests&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 449198 INFO (OverseerThreadFactory-1246-thread-5) [ ] o.a.s.c.CreateCollectionCmd Create collection solrj_replicatests
[junit4] 2> 449403 INFO (qtp5541441-2686) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_replicatests_shard1_replica1&action=CREATE&numShards=1&collection=solrj_replicatests&shard=shard1&wt=javabin&version=2
[junit4] 2> 449404 INFO (qtp15952999-2682) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_replicatests_shard1_replica2&action=CREATE&numShards=1&collection=solrj_replicatests&shard=shard1&wt=javabin&version=2
[junit4] 2> 449507 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 449507 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 450411 INFO (qtp15952999-2682) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.1
[junit4] 2> 450411 INFO (qtp5541441-2686) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.1
[junit4] 2> 450431 INFO (qtp15952999-2682) [ ] o.a.s.s.IndexSchema [solrj_replicatests_shard1_replica2] Schema name=minimal
[junit4] 2> 450433 INFO (qtp5541441-2686) [ ] o.a.s.s.IndexSchema [solrj_replicatests_shard1_replica1] Schema name=minimal
[junit4] 2> 450433 INFO (qtp15952999-2682) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 450434 INFO (qtp15952999-2682) [ ] o.a.s.c.CoreContainer Creating SolrCore 'solrj_replicatests_shard1_replica2' using configuration from collection solrj_replicatests
[junit4] 2> 450434 INFO (qtp15952999-2682) [ ] o.a.s.c.SolrCore [[solrj_replicatests_shard1_replica2] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node4/solrj_replicatests_shard1_replica2], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node4/./solrj_replicatests_shard1_replica2/data/]
[junit4] 2> 450435 INFO (qtp5541441-2686) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 450435 INFO (qtp5541441-2686) [ ] o.a.s.c.CoreContainer Creating SolrCore 'solrj_replicatests_shard1_replica1' using configuration from collection solrj_replicatests
[junit4] 2> 450436 INFO (qtp5541441-2686) [ ] o.a.s.c.SolrCore [[solrj_replicatests_shard1_replica1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node2/solrj_replicatests_shard1_replica1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node2/./solrj_replicatests_shard1_replica1/data/]
[junit4] 2> 450447 INFO (qtp15952999-2682) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 450447 INFO (qtp15952999-2682) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 450452 INFO (qtp15952999-2682) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 450452 INFO (qtp15952999-2682) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 450453 INFO (qtp15952999-2682) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@15166d4[solrj_replicatests_shard1_replica2] main]
[junit4] 2> 450453 INFO (qtp5541441-2686) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 450453 INFO (qtp5541441-2686) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 450453 INFO (qtp15952999-2682) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 450454 INFO (qtp15952999-2682) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 450454 INFO (qtp15952999-2682) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 450454 INFO (searcherExecutor-1265-thread-1) [ ] o.a.s.c.SolrCore [solrj_replicatests_shard1_replica2] Registered new searcher Searcher@15166d4[solrj_replicatests_shard1_replica2] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 450454 INFO (qtp15952999-2682) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1557620661615067136
[junit4] 2> 450460 INFO (qtp15952999-2682) [ ] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard1: total=2 found=1 timeoutin=9999ms
[junit4] 2> 450463 INFO (qtp5541441-2686) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 450464 INFO (qtp5541441-2686) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 450465 INFO (qtp5541441-2686) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@17bae48[solrj_replicatests_shard1_replica1] main]
[junit4] 2> 450465 INFO (qtp5541441-2686) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 450465 INFO (qtp5541441-2686) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 450466 INFO (qtp5541441-2686) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 450466 INFO (searcherExecutor-1266-thread-1) [ ] o.a.s.c.SolrCore [solrj_replicatests_shard1_replica1] Registered new searcher Searcher@17bae48[solrj_replicatests_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 450466 INFO (qtp5541441-2686) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1557620661627650048
[junit4] 2> 450561 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 450561 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 450960 INFO (qtp15952999-2682) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 450960 INFO (qtp15952999-2682) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 450960 INFO (qtp15952999-2682) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:39686/solr/solrj_replicatests_shard1_replica2/
[junit4] 2> 450960 INFO (qtp15952999-2682) [ ] o.a.s.u.PeerSync PeerSync: core=solrj_replicatests_shard1_replica2 url=http://127.0.0.1:39686/solr START replicas=[http://127.0.0.1:37206/solr/solrj_replicatests_shard1_replica1/] nUpdates=100
[junit4] 2> 450961 INFO (qtp15952999-2682) [ ] o.a.s.u.PeerSync PeerSync: core=solrj_replicatests_shard1_replica2 url=http://127.0.0.1:39686/solr DONE. We have no versions. sync failed.
[junit4] 2> 450963 INFO (qtp5541441-2692) [ ] o.a.s.c.S.Request [solrj_replicatests_shard1_replica1] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 450964 INFO (qtp15952999-2682) [ ] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 450964 INFO (qtp15952999-2682) [ ] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4] 2> 450966 INFO (qtp15952999-2682) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:39686/solr/solrj_replicatests_shard1_replica2/ shard1
[junit4] 2> 451068 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 451068 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 451117 INFO (qtp15952999-2682) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 451120 INFO (qtp15952999-2682) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_replicatests_shard1_replica2&action=CREATE&numShards=1&collection=solrj_replicatests&shard=shard1&wt=javabin&version=2} status=0 QTime=1716
[junit4] 2> 451219 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 451219 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 451473 INFO (qtp5541441-2686) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_replicatests_shard1_replica1&action=CREATE&numShards=1&collection=solrj_replicatests&shard=shard1&wt=javabin&version=2} status=0 QTime=2070
[junit4] 2> 451474 INFO (qtp17956584-2666) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
[junit4] 2> 451572 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 451572 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 452475 INFO (qtp17956584-2666) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=2&collection.configName=conf&name=solrj_replicatests&action=CREATE&numShards=1&wt=javabin&version=2} status=0 QTime=3277
[junit4] 2> 452478 INFO (qtp17956584-2662) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :addreplica with params node=127.0.0.1:37206_solr&action=ADDREPLICA&collection=solrj_replicatests&shard=shard1&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 452479 INFO (OverseerThreadFactory-1246-thread-5) [ ] o.a.s.c.AddReplicaCmd addReplica() : {
[junit4] 2> "collection":"solrj_replicatests",
[junit4] 2> "node":"127.0.0.1:37206_solr",
[junit4] 2> "shard":"shard1",
[junit4] 2> "operation":"addreplica"}
[junit4] 2> 452479 INFO (OverseerCollectionConfigSetProcessor-97351290866171910-127.0.0.1:42762_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000008 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 452479 INFO (OverseerThreadFactory-1246-thread-5) [ ] o.a.s.c.AddReplicaCmd Node Identified 127.0.0.1:37206_solr for creating new replica
[junit4] 2> 452481 INFO (qtp5541441-2689) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&name=solrj_replicatests_shard1_replica3&action=CREATE&collection=solrj_replicatests&shard=shard1&wt=javabin&version=2
[junit4] 2> 452584 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 452584 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 453487 INFO (qtp5541441-2689) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.1
[junit4] 2> 453509 INFO (qtp5541441-2689) [ ] o.a.s.s.IndexSchema [solrj_replicatests_shard1_replica3] Schema name=minimal
[junit4] 2> 453510 INFO (qtp5541441-2689) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 453511 INFO (qtp5541441-2689) [ ] o.a.s.c.CoreContainer Creating SolrCore 'solrj_replicatests_shard1_replica3' using configuration from collection solrj_replicatests
[junit4] 2> 453511 INFO (qtp5541441-2689) [ ] o.a.s.c.SolrCore [[solrj_replicatests_shard1_replica3] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node2/solrj_replicatests_shard1_replica3], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node2/./solrj_replicatests_shard1_replica3/data/]
[junit4] 2> 453524 INFO (qtp5541441-2689) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 453524 INFO (qtp5541441-2689) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 453530 INFO (qtp5541441-2689) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 453530 INFO (qtp5541441-2689) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 453531 INFO (qtp5541441-2689) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@e69803[solrj_replicatests_shard1_replica3] main]
[junit4] 2> 453531 INFO (qtp5541441-2689) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 453531 INFO (qtp5541441-2689) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 453531 INFO (qtp5541441-2689) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 453531 INFO (searcherExecutor-1275-thread-1) [ ] o.a.s.c.SolrCore [solrj_replicatests_shard1_replica3] Registered new searcher Searcher@e69803[solrj_replicatests_shard1_replica3] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 453532 INFO (qtp5541441-2689) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1557620664842584064
[junit4] 2> 453535 INFO (qtp5541441-2689) [ ] o.a.s.c.ZkController Core needs to recover:solrj_replicatests_shard1_replica3
[junit4] 2> 453535 INFO (updateExecutor-545-thread-1) [ ] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 453535 INFO (recoveryExecutor-546-thread-1) [ ] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true
[junit4] 2> 453535 INFO (recoveryExecutor-546-thread-1) [ ] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]]
[junit4] 2> 453535 INFO (recoveryExecutor-546-thread-1) [ ] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[solrj_replicatests_shard1_replica3]
[junit4] 2> 453535 INFO (recoveryExecutor-546-thread-1) [ ] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 453535 INFO (recoveryExecutor-546-thread-1) [ ] o.a.s.c.RecoveryStrategy Publishing state of core [solrj_replicatests_shard1_replica3] as recovering, leader is [http://127.0.0.1:39686/solr/solrj_replicatests_shard1_replica2/] and I am [http://127.0.0.1:37206/solr/solrj_replicatests_shard1_replica3/]
[junit4] 2> 453537 INFO (qtp5541441-2689) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&name=solrj_replicatests_shard1_replica3&action=CREATE&collection=solrj_replicatests&shard=shard1&wt=javabin&version=2} status=0 QTime=1056
[junit4] 2> 453538 INFO (recoveryExecutor-546-thread-1) [ ] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:39686/solr]; [WaitForState: action=PREPRECOVERY&core=solrj_replicatests_shard1_replica2&nodeName=127.0.0.1:37206_solr&coreNodeName=core_node3&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
[junit4] 2> 453541 INFO (qtp17956584-2662) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={node=127.0.0.1:37206_solr&action=ADDREPLICA&collection=solrj_replicatests&shard=shard1&wt=javabin&version=2} status=0 QTime=1062
[junit4] 2> 453541 INFO (qtp15952999-2664) [ ] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true
[junit4] 2> 453542 INFO (qtp15952999-2664) [ ] o.a.s.h.a.PrepRecoveryOp Will wait a max of 183 seconds to see solrj_replicatests_shard1_replica2 (shard1 of solrj_replicatests) have state: recovering
[junit4] 2> 453542 INFO (qtp15952999-2664) [ ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=solrj_replicatests, shard=shard1, thisCore=solrj_replicatests_shard1_replica2, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:37206_solr, coreNodeName=core_node3, onlyIfActiveCheckResult=false, nodeProps: core_node3:{"core":"solrj_replicatests_shard1_replica3","base_url":"http://127.0.0.1:37206/solr","node_name":"127.0.0.1:37206_solr","state":"down"}
[junit4] 2> 453546 INFO (qtp17956584-2684) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :deletereplica with params replica=core_node3&action=DELETEREPLICA&collection=solrj_replicatests&shard=shard1&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 453548 INFO (OverseerCollectionConfigSetProcessor-97351290866171910-127.0.0.1:42762_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000010 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 453551 INFO (qtp5541441-2667) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.solrj_replicatests_shard1_replica3
[junit4] 2> 453552 WARN (qtp5541441-2667) [ ] o.a.s.c.RecoveryStrategy Stopping recovery for core=[solrj_replicatests_shard1_replica3] coreNodeName=[core_node3]
[junit4] 2> 453553 INFO (qtp5541441-2667) [ ] o.a.s.c.SolrCore Core solrj_replicatests_shard1_replica3 is not yet closed, waiting 100 ms before checking again.
[junit4] 2> 453554 ERROR (recoveryExecutor-546-thread-1) [ ] o.a.s.c.RecoveryStrategy Error while trying to recover. core=solrj_replicatests_shard1_replica3:java.util.concurrent.ExecutionException: org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: http://127.0.0.1:39686/solr
[junit4] 2> at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
[junit4] 2> at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
[junit4] 2> at org.apache.solr.cloud.RecoveryStrategy.sendPrepRecoveryCmd(RecoveryStrategy.java:614)
[junit4] 2> at org.apache.solr.cloud.RecoveryStrategy.sendPrepRecoveryCmd(RecoveryStrategy.java:591)
[junit4] 2> at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:351)
[junit4] 2> at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:222)
[junit4] 2> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
[junit4] 2> at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514)
[junit4] 2> at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1161)
[junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2> Caused by: org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: http://127.0.0.1:39686/solr
[junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:624)
[junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrClient.lambda$httpUriRequest$0(HttpSolrClient.java:319)
[junit4] 2> ... 5 more
[junit4] 2> Caused by: java.net.SocketException: Socket closed
[junit4] 2> at java.base/java.net.SocketInputStream.read(SocketInputStream.java:203)
[junit4] 2> at java.base/java.net.SocketInputStream.read(SocketInputStream.java:141)
[junit4] 2> at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:160)
[junit4] 2> at org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputBuffer.java:84)
[junit4] 2> at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:273)
[junit4] 2> at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:140)
[junit4] 2> at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)
[junit4] 2> at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:261)
[junit4] 2> at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:283)
[junit4] 2> at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:251)
[junit4] 2> at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:197)
[junit4] 2> at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:272)
[junit4] 2> at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:124)
[junit4] 2> at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:685)
[junit4] 2> at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:487)
[junit4] 2> at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:882)
[junit4] 2> at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
[junit4] 2> at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55)
[junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:515)
[junit4] 2> ... 6 more
[junit4] 2>
[junit4] 2> 453555 INFO (recoveryExecutor-546-thread-1) [ ] o.a.s.c.RecoveryStrategy Replay not started, or was not successful... still buffering updates.
[junit4] 2> 453555 INFO (recoveryExecutor-546-thread-1) [ ] o.a.s.c.RecoveryStrategy RecoveryStrategy has been closed
[junit4] 2> 453555 INFO (recoveryExecutor-546-thread-1) [ ] o.a.s.c.RecoveryStrategy Finished recovery process, successful=[false]
[junit4] 2> 453555 INFO (recoveryExecutor-546-thread-1) [ ] o.a.s.c.SolrCore [solrj_replicatests_shard1_replica3] CLOSING SolrCore org.apache.solr.core.SolrCore@1fb4d25
[junit4] 2> 453556 WARN (recoveryExecutor-546-thread-1) [ ] o.a.s.c.RecoveryStrategy Stopping recovery for core=[solrj_replicatests_shard1_replica3] coreNodeName=[core_node3]
[junit4] 2> 453557 INFO (recoveryExecutor-546-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.solrj_replicatests.shard1.replica3
[junit4] 2> 453638 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 453638 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 453653 INFO (qtp5541441-2667) [ ] o.a.s.c.ShardLeaderElectionContextBase No version found for ephemeral leader parent node, won't remove previous leader registration.
[junit4] 2> 453653 INFO (qtp5541441-2667) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=solrj_replicatests_shard1_replica3&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2&deleteIndex=true} status=0 QTime=103
[junit4] 2> 453755 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 453755 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_replicatests/state.json] for collection [solrj_replicatests] has occurred - updating... (live nodes size: [4])
[junit4] 2> 453856 INFO (qtp17956584-2684) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replica=core_node3&action=DELETEREPLICA&collection=solrj_replicatests&shard=shard1&wt=javabin&version=2} status=0 QTime=310
[junit4] 2> 453858 INFO (TEST-CollectionsAPISolrJTest.testAddAndDeleteReplica-seed#[157992962A846398]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testAddAndDeleteReplica
[junit4] 2> 453888 INFO (TEST-CollectionsAPISolrJTest.testCreateAndDeleteCollection-seed#[157992962A846398]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateAndDeleteCollection
[junit4] 2> 453890 INFO (qtp17956584-2688) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=2&collection.configName=conf&name=solrj_test&action=CREATE&numShards=2&stateFormat=1&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 453891 INFO (OverseerThreadFactory-1246-thread-5) [ ] o.a.s.c.CreateCollectionCmd Create collection solrj_test
[junit4] 2> 453892 INFO (OverseerCollectionConfigSetProcessor-97351290866171910-127.0.0.1:42762_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000012 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 454096 INFO (qtp17956584-2681) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_test_shard1_replica2&action=CREATE&numShards=2&collection=solrj_test&shard=shard1&wt=javabin&version=2
[junit4] 2> 454096 INFO (qtp5541441-2692) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_test_shard1_replica1&action=CREATE&numShards=2&collection=solrj_test&shard=shard1&wt=javabin&version=2
[junit4] 2> 454096 INFO (qtp15952999-2678) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_test_shard2_replica1&action=CREATE&numShards=2&collection=solrj_test&shard=shard2&wt=javabin&version=2
[junit4] 2> 454096 INFO (qtp1953629-2694) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_test_shard2_replica2&action=CREATE&numShards=2&collection=solrj_test&shard=shard2&wt=javabin&version=2
[junit4] 2> 455105 INFO (qtp5541441-2692) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.1
[junit4] 2> 455438 INFO (qtp15952999-2678) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.1
[junit4] 2> 455438 INFO (qtp17956584-2681) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.1
[junit4] 2> 455439 INFO (qtp1953629-2694) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.1
[junit4] 2> 455451 INFO (qtp5541441-2692) [ ] o.a.s.s.IndexSchema [solrj_test_shard1_replica1] Schema name=minimal
[junit4] 2> 455453 INFO (qtp5541441-2692) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 455453 INFO (qtp15952999-2678) [ ] o.a.s.s.IndexSchema [solrj_test_shard2_replica1] Schema name=minimal
[junit4] 2> 455453 INFO (qtp5541441-2692) [ ] o.a.s.c.CoreContainer Creating SolrCore 'solrj_test_shard1_replica1' using configuration from collection solrj_test
[junit4] 2> 455454 INFO (qtp17956584-2681) [ ] o.a.s.s.IndexSchema [solrj_test_shard1_replica2] Schema name=minimal
[junit4] 2> 455454 INFO (qtp5541441-2692) [ ] o.a.s.c.SolrCore [[solrj_test_shard1_replica1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node2/solrj_test_shard1_replica1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node2/./solrj_test_shard1_replica1/data/]
[junit4] 2> 455454 INFO (qtp15952999-2678) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 455454 INFO (qtp1953629-2694) [ ] o.a.s.s.IndexSchema [solrj_test_shard2_replica2] Schema name=minimal
[junit4] 2> 455455 INFO (qtp15952999-2678) [ ] o.a.s.c.CoreContainer Creating SolrCore 'solrj_test_shard2_replica1' using configuration from collection solrj_test
[junit4] 2> 455455 INFO (qtp15952999-2678) [ ] o.a.s.c.SolrCore [[solrj_test_shard2_replica1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node4/solrj_test_shard2_replica1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node4/./solrj_test_shard2_replica1/data/]
[junit4] 2> 455456 INFO (qtp17956584-2681) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 455456 INFO (qtp1953629-2694) [ ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 455457 INFO (qtp17956584-2681) [ ] o.a.s.c.CoreContainer Creating SolrCore 'solrj_test_shard1_replica2' using configuration from collection solrj_test
[junit4] 2> 455457 INFO (qtp1953629-2694) [ ] o.a.s.c.CoreContainer Creating SolrCore 'solrj_test_shard2_replica2' using configuration from collection solrj_test
[junit4] 2> 455457 INFO (qtp17956584-2681) [ ] o.a.s.c.SolrCore [[solrj_test_shard1_replica2] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node1/solrj_test_shard1_replica2], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node1/./solrj_test_shard1_replica2/data/]
[junit4] 2> 455457 INFO (qtp1953629-2694) [ ] o.a.s.c.SolrCore [[solrj_test_shard2_replica2] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node3/solrj_test_shard2_replica2], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.4-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPISolrJTest_157992962A846398-001/tempDir-001/node3/./solrj_test_shard2_replica2/data/]
[junit4] 2> 455481 INFO (qtp15952999-2678) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 455481 INFO (qtp15952999-2678) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 455481 INFO (qtp5541441-2692) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 455481 INFO (qtp5541441-2692) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 455481 INFO (qtp1953629-2694) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 455481 INFO (qtp1953629-2694) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 455495 INFO (qtp15952999-2678) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 455495 INFO (qtp15952999-2678) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 455496 INFO (qtp17956584-2681) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 455496 INFO (qtp17956584-2681) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 455498 INFO (qtp15952999-2678) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@27cb18[solrj_test_shard2_replica1] main]
[junit4] 2> 455498 INFO (qtp15952999-2678) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 455499 INFO (qtp15952999-2678) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 455499 INFO (qtp15952999-2678) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 455499 INFO (searcherExecutor-1281-thread-1) [ ] o.a.s.c.SolrCore [solrj_test_shard2_replica1] Registered new searcher Searcher@27cb18[solrj_test_shard2_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 455499 INFO (qtp5541441-2692) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 455499 INFO (qtp5541441-2692) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 455499 INFO (qtp15952999-2678) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1557620666905133056
[junit4] 2> 455500 INFO (qtp1953629-2694) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 455500 INFO (qtp1953629-2694) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 455500 INFO (qtp5541441-2692) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@3ef9c9[solrj_test_shard1_replica1] main]
[junit4] 2> 455501 INFO (qtp1953629-2694) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@875b3e[solrj_test_shard2_replica2] main]
[junit4] 2> 455501 INFO (qtp5541441-2692) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 455501 INFO (qtp5541441-2692) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 455501 INFO (qtp5541441-2692) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 455502 INFO (qtp17956584-2681) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 455502 INFO (qtp17956584-2681) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 455502 INFO (qtp1953629-2694) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 455502 INFO (searcherExecutor-1280-thread-1) [ ] o.a.s.c.SolrCore [solrj_test_shard1_replica1] Registered new searcher Searcher@3ef9c9[solrj_test_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 455502 INFO (qtp5541441-2692) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1557620666908278784
[junit4] 2> 455502 INFO (qtp1953629-2694) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 455502 INFO (qtp1953629-2694) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 455502 INFO (qtp1953629-2694) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1557620666908278784
[junit4] 2> 455502 INFO (qtp17956584-2681) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@1d7b16f[solrj_test_shard1_replica2] main]
[junit4] 2> 455503 INFO (qtp17956584-2681) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 455503 INFO (searcherExecutor-1283-thread-1) [ ] o.a.s.c.SolrCore [solrj_test_shard2_replica2] Registered new searcher Searcher@875b3e[solrj_test_shard2_replica2] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 455503 INFO (qtp17956584-2681) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 455504 INFO (qtp17956584-2681) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 455504 INFO (qtp17956584-2681) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1557620666910375936
[junit4] 2> 455505 INFO (searcherExecutor-1282-thread-1) [ ] o.a.s.c.SolrCore [solrj_test_shard1_replica2] Registered new searcher Searcher@1d7b16f[solrj_test_shard1_replica2] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 455506 INFO (qtp15952999-2678) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 455506 INFO (qtp15952999-2678) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 455506 INFO (qtp15952999-2678) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:39686/solr/solrj_test_shard2_replica1/
[junit4] 2> 455506 INFO (qtp15952999-2678) [ ] o.a.s.u.PeerSync PeerSync: core=solrj_test_shard2_replica1 url=http://127.0.0.1:39686/solr START replicas=[http://127.0.0.1:42762/solr/solrj_test_shard2_replica2/] nUpdates=100
[junit4] 2> 455506 INFO (qtp15952999-2678) [ ] o.a.s.u.PeerSync PeerSync: core=solrj_test_shard2_replica1 url=http://127.0.0.1:39686/solr DONE. We have no versions. sync failed.
[junit4] 2> 455512 INFO (qtp1953629-2672) [ ] o.a.s.c.S.Request [solrj_test_shard2_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 455512 INFO (qtp5541441-2692) [ ] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard1: total=2 found=1 timeoutin=9999ms
[junit4] 2> 455512 INFO (qtp15952999-2678) [ ] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 455512 INFO (qtp15952999-2678) [ ] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4] 2> 455514 INFO (qtp15952999-2678) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:39686/solr/solrj_test_shard2_replica1/ shard2
[junit4] 2> 455665 INFO (qtp15952999-2678) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 455669 INFO (qtp15952999-2678) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_test_shard2_replica1&action=CREATE&numShards=2&collection=solrj_test&shard=shard2&wt=javabin&version=2} status=0 QTime=1573
[junit4] 2> 456012 INFO (qtp5541441-2692) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 456012 INFO (qtp5541441-2692) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 456013 INFO (qtp5541441-2692) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:37206/solr/solrj_test_shard1_replica1/
[junit4] 2> 456013 INFO (qtp5541441-2692) [ ] o.a.s.u.PeerSync PeerSync: core=solrj_test_shard1_replica1 url=http://127.0.0.1:37206/solr START replicas=[http://127.0.0.1:36225/solr/solrj_test_shard1_replica2/] nUpdates=100
[junit4] 2> 456013 INFO (qtp5541441-2692) [ ] o.a.s.u.PeerSync PeerSync: core=solrj_test_shard1_replica1 url=http://127.0.0.1:37206/solr DONE. We have no versions. sync failed.
[junit4] 2> 456015 INFO (qtp17956584-2669) [ ] o.a.s.c.S.Request [solrj_test_shard1_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 456016 INFO (qtp5541441-2692) [ ] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 456016 INFO (qtp5541441-2692) [ ] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4] 2> 456019 INFO (qtp5541441-2692) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:37206/solr/solrj_test_shard1_replica1/ shard1
[junit4] 2> 456170 INFO (qtp5541441-2692) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 456173 INFO (qtp5541441-2692) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_test_shard1_replica1&action=CREATE&numShards=2&collection=solrj_test&shard=shard1&wt=javabin&version=2} status=0 QTime=2077
[junit4] 2> 456516 INFO (qtp17956584-2681) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_test_shard1_replica2&action=CREATE&numShards=2&collection=solrj_test&shard=shard1&wt=javabin&version=2} status=0 QTime=2419
[junit4] 2> 456517 INFO (qtp1953629-2694) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_test_shard2_replica2&action=CREATE&numShards=2&collection=solrj_test&shard=shard2&wt=javabin&version=2} status=0 QTime=2420
[junit4] 2> 456518 INFO (qtp17956584-2688) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
[junit4] 2> 457519 INFO (qtp17956584-2688) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=2&collection.configName=conf&name=solrj_test&action=CREATE&numShards=2&stateFormat=1&wt=javabin&version=2} status=0 QTime=3628
[junit4] 2> 457521 INFO (qtp17956584-2666) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=solrj_test&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 457522 INFO (OverseerThreadFactory-1246-thread-5) [ ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true
[junit4] 2> 457523 INFO (OverseerCollectionConfigSetProcessor-97351290866171910-127.0.0.1:42762_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000014 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 457525 INFO (qtp15952999-2687) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.solrj_test_shard2_replica1
[junit4] 2> 457526 INFO (qtp15952999-2687) [ ] o.a.s.c.SolrCore [solrj_test_shard2_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@1476b96
[junit4] 2> 457526 INFO (qtp1953629-2697) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.solrj_test_shard2_replica2
[junit4] 2> 457526 INFO (qtp17956584-2662) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.solrj_test_shard1_replica2
[junit4] 2> 457526 INFO (qtp1953629-2697) [ ] o.a.s.c.SolrCore [solrj_test_shard2_replica2] CLOSING SolrCore org.apache.solr.core.SolrCore@14c4d8d
[junit4] 2> 457527 INFO (qtp17956584-2662) [ ] o.a.s.c.SolrCore [solrj_test_shard1_replica2] CLOSING SolrCore org.apache.solr.core.SolrCore@17f6c8c
[junit4] 2> 457531 INFO (qtp5541441-2686) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.solrj_test_shard1_replica1
[junit4] 2> 457531 INFO (qtp5541441-2686) [ ] o.a.s.c.SolrCore [solrj_test_shard1_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@1d93a02
[junit4] 2> 457532 INFO (qtp17956584-2662) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.solrj_test.shard1.replica2
[junit4] 2> 457532 INFO (qtp15952999-2687) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.solrj_test.shard2.replica1
[junit4] 2> 457532 INFO (qtp1953629-2697) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.solrj_test.shard2.replica2
[junit4] 2> 457533 INFO (qtp5541441-2686) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.solrj_test.shard1.replica1
[junit4] 2> 457547 INFO (qtp5541441-2686) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=solrj_test_shard1_replica1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=20
[junit4] 2> 457547 WARN (zkCallback-553-thread-1) [ ] o.a.s.c.LeaderElector
[junit4] 2> org.apache.solr.common.SolrException: SolrCore not found:solrj_test_shard1_replica2 in [solrj_test_core_props_shard1_replica1]
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:292)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:170)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:135)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:56)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:348)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.lambda$process$0(SolrZkClient.java:268)
[junit4] 2> at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514)
[junit4] 2> at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1161)
[junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2> 457551 WARN (zkCallback-544-thread-1) [ ] o.a.s.c.LeaderElector
[junit4] 2> org.apache.solr.common.SolrException: SolrCore not found:solrj_test_shard2_replica2 in []
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:292)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:170)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:135)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:56)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:348)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.lambda$process$0(SolrZkClient.java:268)
[junit4] 2> at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514)
[junit4] 2> at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1161)
[junit4] 2> at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2> 457551 INFO (qtp15952999-2687) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=solrj_test_shard2_replica1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=26
[junit4] 2> 457554 INFO (qtp17956584-2662) [ ] o.a.s.c.ShardLeaderElectionContextBase No version found for ephemeral leader parent node, won't remove previous leader registration.
[junit4] 2> 457555 INFO (qtp1953629-2697) [ ] o.a.s.c.ShardLeaderElectionContextBase No version found for ephemeral leader parent node, won't remove previous leader registration.
[junit4] 2> 457555 INFO (qtp17956584-2662) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=solrj_test_shard1_replica2&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=30
[junit4] 2> 457555 INFO (qtp1953629-2697) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=solrj_test_shard2_replica2&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=31
[junit4] 2> 458258 INFO (qtp17956584-2666) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=solrj_test&action=DELETE&wt=javabin&version=2} status=0 QTime=736
[junit4] 2> 458261 INFO (qtp17956584-2669) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=2&collection.configName=conf&name=solrj_newstateformat&action=CREATE&numShards=2&stateFormat=2&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 458262 INFO (OverseerThreadFactory-1246-thread-5) [ ] o.a.s.c.CreateCollectionCmd Create collection solrj_newstateformat
[junit4] 2> 458262 INFO (OverseerCollectionConfigSetProcessor-97351290866171910-127.0.0.1:42762_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000016 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 458466 INFO (qtp1953629-2665) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_newstateformat_shard2_replica2&action=CREATE&numShards=2&collection=solrj_newstateformat&shard=shard2&wt=javabin&version=2
[junit4] 2> 458466 INFO (qtp15952999-2668) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_newstateformat_shard1_replica1&action=CREATE&numShards=2&collection=solrj_newstateformat&shard=shard1&wt=javabin&version=2
[junit4] 2> 458466 INFO (qtp17956584-2813) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_newstateformat_shard1_replica2&action=CREATE&numShards=2&collection=solrj_newstateformat&shard=shard1&wt=javabin&version=2
[junit4] 2> 458466 INFO (qtp5541441-2689) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=solrj_newstateformat_shard2_replica1&action=CREATE&numShards=2&collection=solrj_newstateformat&shard=shard2&wt=javabin&version=2
[junit4] 2> 458572 INFO (zkCallback-544-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_newstateformat/state.json] for collection [solrj_newstateformat] has occurred - updating... (live nodes size: [4])
[junit4] 2> 458572 INFO (zkCallback-556-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_newstateformat/state.json] for collection [solrj_newstateformat] has occurred - updating... (live nodes size: [4])
[junit4] 2> 458572 INFO (zkCallback-553-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_newstateformat/state.json] for collection [solrj_newstateformat] has occurred - updating... (live nodes size: [4])
[junit4] 2> 458572 INFO (zkCallback-551-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/solrj_newstateformat/state.json] for collection [solrj_newstateformat] has occurred - updating... (live nodes size
[...truncated too long message...]
ervletHandler.java:512)
[junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
[junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
[junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
[junit4] 2> at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:462)
[junit4] 2> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
[junit4] 2> at org.eclipse.jetty.server.Server.handle(Server.java:534)
[junit4] 2> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
[junit4] 2> at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
[junit4] 2> at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
[junit4] 2> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
[junit4] 2> at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
[junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
[junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
[junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
[junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2>
[junit4] 2> 489548 INFO (qtp15952999-2664) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:37206_solr&onlyIfLeaderActive=true&core=solrj_replicatests_shard1_replica2&coreNodeName=core_node3&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=400 QTime=36006
[junit4] 2> 490491 WARN (OverseerStateUpdate-97351290866171910-127.0.0.1:42762_solr-n_0000000004) [ ] o.a.s.c.Overseer Solr cannot talk to ZK, exiting Overseer work queue loop
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer/queue-work
[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:339)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:336)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:60)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:336)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.fetchZkChildren(DistributedQueue.java:299)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.firstChild(DistributedQueue.java:279)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.firstElement(DistributedQueue.java:384)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.peek(DistributedQueue.java:124)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:148)
[junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2> 490492 INFO (OverseerStateUpdate-97351290866171910-127.0.0.1:42762_solr-n_0000000004) [ ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:42762_solr
[junit4] 2> 490496 WARN (zkCallback-544-thread-1) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 490496 INFO (jetty-launcher-533-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.node
[junit4] 2> 490496 INFO (jetty-launcher-533-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@1866ca4{/solr,null,UNAVAILABLE}
[junit4] 2> 490497 INFO (SUITE-CollectionsAPISolrJTest-seed#[157992962A846398]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:46718 46718
[junit4] 2> 490550 INFO (Thread-536) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:46718 46718
[junit4] 2> 490551 WARN (Thread-536) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 5 /solr/collections/solrj_test/state.json
[junit4] 2> 5 /solr/aliases.json
[junit4] 2> 5 /solr/configs/conf
[junit4] 2> 5 /solr/clusterprops.json
[junit4] 2> 4 /solr/security.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 7 /solr/collections/replicaProperties/state.json
[junit4] 2> 5 /solr/clusterprops.json
[junit4] 2> 5 /solr/collections/balancedProperties/state.json
[junit4] 2> 5 /solr/clusterstate.json
[junit4] 2> 5 /solr/collections/solrj_newstateformat/state.json
[junit4] 2> 3 /solr/collections/solrj_implicit/state.json
[junit4] 2> 3 /solr/collections/solrj_test_splitshard/state.json
[junit4] 2> 3 /solr/collections/solrj_replicatests/state.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 98 /solr/overseer/queue
[junit4] 2> 15 /solr/overseer/queue-work
[junit4] 2> 10 /solr/overseer/collection-queue-work
[junit4] 2> 5 /solr/live_nodes
[junit4] 2> 5 /solr/collections
[junit4] 2>
[junit4] 2> 490552 INFO (SUITE-CollectionsAPISolrJTest-seed#[157992962A846398]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> Jan 26, 2017 8:34:19 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 3 leaked thread(s).
[junit4] 2> 490992 WARN (OverseerCollectionConfigSetProcessor-97351290866171910-127.0.0.1:42762_solr-n_0000000004) [ ] o.a.s.c.OverseerTaskProcessor Overseer cannot talk to ZK
[junit4] 2> Jan 26, 2017 8:34:39 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> SEVERE: 1 thread leaked from SUITE scope at org.apache.solr.cloud.CollectionsAPISolrJTest:
[junit4] 2> 1) Thread[id=2941, name=OverseerHdfsCoreFailoverThread-97351290866171910-127.0.0.1:42762_solr-n_0000000004, state=TIMED_WAITING, group=Overseer Hdfs SolrCore Failover Thread.]
[junit4] 2> at java.base@9-ea/java.lang.Thread.sleep(Native Method)
[junit4] 2> at app//org.apache.solr.cloud.OverseerAutoReplicaFailoverThread.run(OverseerAutoReplicaFailoverThread.java:139)
[junit4] 2> at java.base@9-ea/java.lang.Thread.run(Thread.java:844)
[junit4] 2> Jan 26, 2017 8:34:39 PM com.carrotsearch.randomizedtesting.ThreadLeakControl tryToInterruptAll
[junit4] 2> INFO: Starting to interrupt leaked threads:
[junit4] 2> 1) Thread[id=2941, name=OverseerHdfsCoreFailoverThread-97351290866171910-127.0.0.1:42762_solr-n_0000000004, state=TIMED_WAITING, group=Overseer Hdfs SolrCore Failover Thread.]
[junit4] 2> Jan 26, 2017 8:34:39 PM com.carrotsearch.randomizedtesting.ThreadLeakControl tryToInterruptAll
[junit4] 2> INFO: All leaked threads terminated.
[junit4] 2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarity(queryNorm=false,coord=yes): {}, locale=ckb, timezone=Etc/GMT-9
[junit4] 2> NOTE: Linux 4.4.0-53-generic i386/Oracle Corporation 9-ea (32-bit)/cpus=12,threads=1,free=68554464,total=220262400
[junit4] 2> NOTE: All tests run in this JVM: [TestConfigSetsAPIZkFailure, SolrCloudExampleTest, TemplateUpdateProcessorTest, TestDynamicFieldCollectionResource, TestReload, LeaderElectionTest, TestImpersonationWithHadoopAuth, TestMergePolicyConfig, CdcrBootstrapTest, TestSolrQueryResponse, GraphQueryTest, TestPerFieldSimilarityClassic, SuggesterWFSTTest, HdfsBasicDistributedZk2Test, AutoCommitTest, QueryParsingTest, TestAnalyzedSuggestions, TestGeoJSONResponseWriter, TestFieldResource, TestShardHandlerFactory, TestSolrQueryParserResource, TestUtils, ShowFileRequestHandlerTest, TermVectorComponentDistributedTest, LukeRequestHandlerTest, TestJmxMonitoredMap, SolrCoreMetricManagerTest, BadIndexSchemaTest, TestCollectionAPI, TestZkChroot, TestFieldCacheVsDocValues, TestUnifiedSolrHighlighter, LeaderFailoverAfterPartitionTest, CollectionsAPISolrJTest]
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=CollectionsAPISolrJTest -Dtests.seed=157992962A846398 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ckb -Dtests.timezone=Etc/GMT-9 -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] ERROR 0.00s J2 | CollectionsAPISolrJTest (suite) <<<
[junit4] > Throwable #1: com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.CollectionsAPISolrJTest:
[junit4] > 1) Thread[id=2941, name=OverseerHdfsCoreFailoverThread-97351290866171910-127.0.0.1:42762_solr-n_0000000004, state=TIMED_WAITING, group=Overseer Hdfs SolrCore Failover Thread.]
[junit4] > at java.base@9-ea/java.lang.Thread.sleep(Native Method)
[junit4] > at app//org.apache.solr.cloud.OverseerAutoReplicaFailoverThread.run(OverseerAutoReplicaFailoverThread.java:139)
[junit4] > at java.base@9-ea/java.lang.Thread.run(Thread.java:844)
[junit4] > at __randomizedtesting.SeedInfo.seed([157992962A846398]:0)
[junit4] Completed [130/680 (1!)] on J2 in 67.66s, 12 tests, 1 error <<< FAILURES!
[...truncated 53341 lines...]