You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2018/03/02 07:50:57 UTC
[JENKINS] Lucene-Solr-Tests-6.6 - Build # 45 - Still unstable
Build: https://builds.apache.org/job/Lucene-Solr-Tests-6.6/45/
2 tests failed.
FAILED: org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI
Error Message:
Something is broken in the assert for no shards using the same indexDir - probably something was changed in the attributes published in the MBean of SolrCore : {}
Stack Trace:
java.lang.AssertionError: Something is broken in the assert for no shards using the same indexDir - probably something was changed in the attributes published in the MBean of SolrCore : {}
at __randomizedtesting.SeedInfo.seed([CB4E4B01BDAA51DA:833B3FB5BB997E4F]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.checkNoTwoShardsUseTheSameIndexDir(CollectionsAPIDistributedZkTest.java:646)
at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI(CollectionsAPIDistributedZkTest.java:524)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:748)
FAILED: org.apache.solr.cloud.LegacyCloudClusterPropTest.testCreateCollectionSwitchLegacyCloud
Error Message:
Should have found property replicaType in properties file
Stack Trace:
java.lang.AssertionError: Should have found property replicaType in properties file
at __randomizedtesting.SeedInfo.seed([CB4E4B01BDAA51DA:1A49B98419A5DAE8]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.LegacyCloudClusterPropTest.checkMandatoryProps(LegacyCloudClusterPropTest.java:158)
at org.apache.solr.cloud.LegacyCloudClusterPropTest.createAndTest(LegacyCloudClusterPropTest.java:90)
at org.apache.solr.cloud.LegacyCloudClusterPropTest.testCreateCollectionSwitchLegacyCloud(LegacyCloudClusterPropTest.java:69)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:748)
Build Log:
[...truncated 11532 lines...]
[junit4] Suite: org.apache.solr.cloud.LegacyCloudClusterPropTest
[junit4] 2> Creating dataDir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.LegacyCloudClusterPropTest_CB4E4B01BDAA51DA-001/init-core-data-001
[junit4] 2> 244973 WARN (SUITE-LegacyCloudClusterPropTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=14 numCloses=14
[junit4] 2> 244973 INFO (SUITE-LegacyCloudClusterPropTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields
[junit4] 2> 244975 INFO (SUITE-LegacyCloudClusterPropTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
[junit4] 2> 244975 INFO (SUITE-LegacyCloudClusterPropTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 1 servers in /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.LegacyCloudClusterPropTest_CB4E4B01BDAA51DA-001/tempDir-001
[junit4] 2> 244975 INFO (SUITE-LegacyCloudClusterPropTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 244976 INFO (Thread-1030) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 244976 INFO (Thread-1030) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 244980 ERROR (Thread-1030) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 245076 INFO (SUITE-LegacyCloudClusterPropTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:37640
[junit4] 2> 245081 INFO (jetty-launcher-629-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 245082 INFO (jetty-launcher-629-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@76c7edd6{/solr,null,AVAILABLE}
[junit4] 2> 245084 INFO (jetty-launcher-629-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@43492ecf{HTTP/1.1,[http/1.1]}{127.0.0.1:57841}
[junit4] 2> 245084 INFO (jetty-launcher-629-thread-1) [ ] o.e.j.s.Server Started @247327ms
[junit4] 2> 245085 INFO (jetty-launcher-629-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=57841}
[junit4] 2> 245085 ERROR (jetty-launcher-629-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 245085 INFO (jetty-launcher-629-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.3
[junit4] 2> 245085 INFO (jetty-launcher-629-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 245085 INFO (jetty-launcher-629-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 245085 INFO (jetty-launcher-629-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-03-02T07:10:17.202Z
[junit4] 2> 245087 INFO (jetty-launcher-629-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 245107 INFO (jetty-launcher-629-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 245107 INFO (jetty-launcher-629-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:37640/solr
[junit4] 2> 245149 INFO (jetty-launcher-629-thread-1) [n:127.0.0.1:57841_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 245150 INFO (jetty-launcher-629-thread-1) [n:127.0.0.1:57841_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:57841_solr
[junit4] 2> 245152 INFO (jetty-launcher-629-thread-1) [n:127.0.0.1:57841_solr ] o.a.s.c.Overseer Overseer (id=99613056505872387-127.0.0.1:57841_solr-n_0000000000) starting
[junit4] 2> 245175 INFO (jetty-launcher-629-thread-1) [n:127.0.0.1:57841_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57841_solr
[junit4] 2> 245179 INFO (zkCallback-636-thread-1-processing-n:127.0.0.1:57841_solr) [n:127.0.0.1:57841_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 245285 INFO (jetty-launcher-629-thread-1) [n:127.0.0.1:57841_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.LegacyCloudClusterPropTest_CB4E4B01BDAA51DA-001/tempDir-001/node1/.
[junit4] 2> 245321 INFO (SUITE-LegacyCloudClusterPropTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 245325 INFO (SUITE-LegacyCloudClusterPropTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:37640/solr ready
[junit4] 2> 245336 INFO (TEST-LegacyCloudClusterPropTest.testCreateCollectionSwitchLegacyCloud-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateCollectionSwitchLegacyCloud
[junit4] 2> 245354 INFO (qtp152708473-3427) [n:127.0.0.1:57841_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :clusterprop with params val=true&name=legacyCloud&action=CLUSTERPROP&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 245357 INFO (qtp152708473-3427) [n:127.0.0.1:57841_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={val=true&name=legacyCloud&action=CLUSTERPROP&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 245362 INFO (qtp152708473-3428) [n:127.0.0.1:57841_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf&maxShardsPerNode=1&name=legacyTrue&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 245364 INFO (OverseerThreadFactory-1524-thread-1-processing-n:127.0.0.1:57841_solr) [n:127.0.0.1:57841_solr ] o.a.s.c.CreateCollectionCmd Create collection legacyTrue
[junit4] 2> 245471 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=legacyTrue_shard1_replica1&action=CREATE&numShards=1&collection=legacyTrue&shard=shard1&wt=javabin&version=2
[junit4] 2> 245471 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 245575 INFO (zkCallback-636-thread-1-processing-n:127.0.0.1:57841_solr) [n:127.0.0.1:57841_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/legacyTrue/state.json] for collection [legacyTrue] has occurred - updating... (live nodes size: [1])
[junit4] 2> 246483 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.3
[junit4] 2> 246489 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.s.IndexSchema [legacyTrue_shard1_replica1] Schema name=minimal
[junit4] 2> 246491 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 246491 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.CoreContainer Creating SolrCore 'legacyTrue_shard1_replica1' using configuration from collection legacyTrue, trusted=true
[junit4] 2> 246491 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 246491 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.SolrCore [[legacyTrue_shard1_replica1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.LegacyCloudClusterPropTest_CB4E4B01BDAA51DA-001/tempDir-001/node1/legacyTrue_shard1_replica1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.LegacyCloudClusterPropTest_CB4E4B01BDAA51DA-001/tempDir-001/node1/./legacyTrue_shard1_replica1/data/]
[junit4] 2> 246521 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 246521 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 246522 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 246522 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 246523 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@d834ae6[legacyTrue_shard1_replica1] main]
[junit4] 2> 246524 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 246525 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 246525 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 246525 INFO (searcherExecutor-1527-thread-1-processing-n:127.0.0.1:57841_solr x:legacyTrue_shard1_replica1 s:shard1 c:legacyTrue) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.SolrCore [legacyTrue_shard1_replica1] Registered new searcher Searcher@d834ae6[legacyTrue_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 246526 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1593808905718202368
[junit4] 2> 246531 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 246531 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 246531 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:57841/solr/legacyTrue_shard1_replica1/
[junit4] 2> 246531 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 246531 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.SyncStrategy http://127.0.0.1:57841/solr/legacyTrue_shard1_replica1/ has no replicas
[junit4] 2> 246531 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 246534 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:57841/solr/legacyTrue_shard1_replica1/ shard1
[junit4] 2> 246636 INFO (zkCallback-636-thread-2-processing-n:127.0.0.1:57841_solr) [n:127.0.0.1:57841_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/legacyTrue/state.json] for collection [legacyTrue] has occurred - updating... (live nodes size: [1])
[junit4] 2> 246685 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 246687 INFO (qtp152708473-3430) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 x:legacyTrue_shard1_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=legacyTrue_shard1_replica1&action=CREATE&numShards=1&collection=legacyTrue&shard=shard1&wt=javabin&version=2} status=0 QTime=1216
[junit4] 2> 246695 INFO (qtp152708473-3428) [n:127.0.0.1:57841_solr ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
[junit4] 2> 246789 INFO (zkCallback-636-thread-2-processing-n:127.0.0.1:57841_solr) [n:127.0.0.1:57841_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/legacyTrue/state.json] for collection [legacyTrue] has occurred - updating... (live nodes size: [1])
[junit4] 2> 247370 INFO (OverseerCollectionConfigSetProcessor-99613056505872387-127.0.0.1:57841_solr-n_0000000000) [n:127.0.0.1:57841_solr ] 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> 247695 INFO (qtp152708473-3428) [n:127.0.0.1:57841_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf&maxShardsPerNode=1&name=legacyTrue&action=CREATE&numShards=1&wt=javabin&version=2} status=0 QTime=2333
[junit4] 2> 247698 INFO (TEST-LegacyCloudClusterPropTest.testCreateCollectionSwitchLegacyCloud-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreateCollectionSwitchLegacyCloud
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=LegacyCloudClusterPropTest -Dtests.method=testCreateCollectionSwitchLegacyCloud -Dtests.seed=CB4E4B01BDAA51DA -Dtests.multiplier=2 -Dtests.slow=true -Dtests.locale=es-GT -Dtests.timezone=VST -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[junit4] FAILURE 2.37s J2 | LegacyCloudClusterPropTest.testCreateCollectionSwitchLegacyCloud <<<
[junit4] > Throwable #1: java.lang.AssertionError: Should have found property replicaType in properties file
[junit4] > at __randomizedtesting.SeedInfo.seed([CB4E4B01BDAA51DA:1A49B98419A5DAE8]:0)
[junit4] > at org.apache.solr.cloud.LegacyCloudClusterPropTest.checkMandatoryProps(LegacyCloudClusterPropTest.java:158)
[junit4] > at org.apache.solr.cloud.LegacyCloudClusterPropTest.createAndTest(LegacyCloudClusterPropTest.java:90)
[junit4] > at org.apache.solr.cloud.LegacyCloudClusterPropTest.testCreateCollectionSwitchLegacyCloud(LegacyCloudClusterPropTest.java:69)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 247701 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 0x161e58c10060005, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 247703 INFO (jetty-closer-630-thread-1) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@43492ecf{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 247703 INFO (jetty-closer-630-thread-1) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=607123148
[junit4] 2> 247703 INFO (jetty-closer-630-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.node
[junit4] 2> 247703 INFO (jetty-closer-630-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jvm
[junit4] 2> 247703 INFO (jetty-closer-630-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jetty
[junit4] 2> 247705 INFO (coreCloseExecutor-1532-thread-1) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 r:core_node1 x:legacyTrue_shard1_replica1] o.a.s.c.SolrCore [legacyTrue_shard1_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@ec96e2d
[junit4] 2> 247705 INFO (coreCloseExecutor-1532-thread-1) [n:127.0.0.1:57841_solr c:legacyTrue s:shard1 r:core_node1 x:legacyTrue_shard1_replica1] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.legacyTrue.shard1.replica1
[junit4] 2> 247706 INFO (jetty-closer-630-thread-1) [ ] o.a.s.c.Overseer Overseer (id=99613056505872387-127.0.0.1:57841_solr-n_0000000000) closing
[junit4] 2> 247706 INFO (OverseerStateUpdate-99613056505872387-127.0.0.1:57841_solr-n_0000000000) [n:127.0.0.1:57841_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:57841_solr
[junit4] 2> 249207 WARN (zkCallback-636-thread-2-processing-n:127.0.0.1:57841_solr) [n:127.0.0.1:57841_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 249208 INFO (jetty-closer-630-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@76c7edd6{/solr,null,UNAVAILABLE}
[junit4] 2> 249208 ERROR (SUITE-LegacyCloudClusterPropTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 249209 INFO (SUITE-LegacyCloudClusterPropTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:37640 37640
[junit4] 2> 249379 INFO (Thread-1030) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:37640 37640
[junit4] 2> 249380 WARN (Thread-1030) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 2 /solr/aliases.json
[junit4] 2> 2 /solr/clusterprops.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 2 /solr/clusterstate.json
[junit4] 2> 2 /solr/clusterprops.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 2 /solr/live_nodes
[junit4] 2> 2 /solr/collections
[junit4] 2>
[junit4] 2> 249380 INFO (SUITE-LegacyCloudClusterPropTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.LegacyCloudClusterPropTest_CB4E4B01BDAA51DA-001
[junit4] 2> Mar 02, 2018 7:10:21 AM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene62): {}, docValues:{}, maxPointsInLeafNode=618, maxMBSortInHeap=6.855833757422597, sim=RandomSimilarity(queryNorm=true,coord=yes): {}, locale=es-GT, timezone=VST
[junit4] 2> NOTE: Linux 3.13.0-88-generic amd64/Oracle Corporation 1.8.0_144 (64-bit)/cpus=4,threads=1,free=222728640,total=524812288
[junit4] 2> NOTE: All tests run in this JVM: [QueryParsingTest, TermVectorComponentDistributedTest, TestTestInjection, TestReload, TestRandomRequestDistribution, TestUseDocValuesAsStored2, SolrCoreMetricManagerTest, TestCoreDiscovery, SolrCoreCheckLockOnStartupTest, CdcrReplicationDistributedZkTest, TestDynamicLoading, PrimUtilsTest, SuggesterTSTTest, TestCollationField, TestReqParamsAPI, PingRequestHandlerTest, DistributedQueryComponentOptimizationTest, TestFieldCacheWithThreads, TestExclusionRuleCollectionAccess, TestCloudPivotFacet, HdfsDirectoryTest, TestUnifiedSolrHighlighter, TestSolrCloudWithDelegationTokens, BlockCacheTest, NoCacheHeaderTest, TestJsonFacetRefinement, TestFieldTypeResource, LukeRequestHandlerTest, TestSolrCoreSnapshots, TestPhraseSuggestions, RequestHandlersTest, SharedFSAutoReplicaFailoverUtilsTest, TestCustomSort, XmlUpdateRequestHandlerTest, TestCloudManagedSchema, DistributedFacetPivotLargeTest, PKIAuthenticationIntegrationTest, TestSolrFieldCacheMBean, TestSystemCollAutoCreate, LegacyCloudClusterPropTest]
[junit4] Completed [56/714 (1!)] on J2 in 4.93s, 1 test, 1 failure <<< FAILURES!
[...truncated 755 lines...]
[junit4] Suite: org.apache.solr.cloud.CollectionsAPIDistributedZkTest
[junit4] 2> Creating dataDir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/init-core-data-001
[junit4] 2> 790269 WARN (SUITE-CollectionsAPIDistributedZkTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=8 numCloses=8
[junit4] 2> 790269 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.SolrTestCaseJ4 Using TrieFields
[junit4] 2> 790270 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
[junit4] 2> 790271 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 4 servers in /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-001
[junit4] 2> 790271 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 790271 INFO (Thread-3007) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 790271 INFO (Thread-3007) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 790279 ERROR (Thread-3007) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 790371 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:57579
[junit4] 2> 790384 INFO (jetty-launcher-1520-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 790385 INFO (jetty-launcher-1520-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 790386 INFO (jetty-launcher-1520-thread-3) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 790387 INFO (jetty-launcher-1520-thread-4) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 790391 INFO (jetty-launcher-1520-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@6abe088a{/solr,null,AVAILABLE}
[junit4] 2> 790392 INFO (jetty-launcher-1520-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@56235125{SSL,[ssl, http/1.1]}{127.0.0.1:54009}
[junit4] 2> 790393 INFO (jetty-launcher-1520-thread-1) [ ] o.e.j.s.Server Started @792635ms
[junit4] 2> 790393 INFO (jetty-launcher-1520-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=54009}
[junit4] 2> 790393 ERROR (jetty-launcher-1520-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 790393 INFO (jetty-launcher-1520-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.3
[junit4] 2> 790393 INFO (jetty-launcher-1520-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 790393 INFO (jetty-launcher-1520-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 790393 INFO (jetty-launcher-1520-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-03-02T07:19:22.510Z
[junit4] 2> 790408 INFO (jetty-launcher-1520-thread-3) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@f86aed7{/solr,null,AVAILABLE}
[junit4] 2> 790408 INFO (jetty-launcher-1520-thread-3) [ ] o.e.j.s.AbstractConnector Started ServerConnector@41a62890{SSL,[ssl, http/1.1]}{127.0.0.1:54753}
[junit4] 2> 790408 INFO (jetty-launcher-1520-thread-3) [ ] o.e.j.s.Server Started @792650ms
[junit4] 2> 790408 INFO (jetty-launcher-1520-thread-3) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=54753}
[junit4] 2> 790408 ERROR (jetty-launcher-1520-thread-3) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 790409 INFO (jetty-launcher-1520-thread-3) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.3
[junit4] 2> 790409 INFO (jetty-launcher-1520-thread-3) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 790409 INFO (jetty-launcher-1520-thread-3) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 790409 INFO (jetty-launcher-1520-thread-3) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-03-02T07:19:22.526Z
[junit4] 2> 790413 INFO (jetty-launcher-1520-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@26485f55{/solr,null,AVAILABLE}
[junit4] 2> 790413 INFO (jetty-launcher-1520-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@2ed1e932{SSL,[ssl, http/1.1]}{127.0.0.1:57341}
[junit4] 2> 790413 INFO (jetty-launcher-1520-thread-2) [ ] o.e.j.s.Server Started @792655ms
[junit4] 2> 790413 INFO (jetty-launcher-1520-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=57341}
[junit4] 2> 790413 ERROR (jetty-launcher-1520-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 790413 INFO (jetty-launcher-1520-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.3
[junit4] 2> 790414 INFO (jetty-launcher-1520-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 790414 INFO (jetty-launcher-1520-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 790414 INFO (jetty-launcher-1520-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-03-02T07:19:22.531Z
[junit4] 2> 790415 INFO (jetty-launcher-1520-thread-4) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@77ea2124{/solr,null,AVAILABLE}
[junit4] 2> 790416 INFO (jetty-launcher-1520-thread-4) [ ] o.e.j.s.AbstractConnector Started ServerConnector@5352f974{SSL,[ssl, http/1.1]}{127.0.0.1:55895}
[junit4] 2> 790416 INFO (jetty-launcher-1520-thread-4) [ ] o.e.j.s.Server Started @792658ms
[junit4] 2> 790416 INFO (jetty-launcher-1520-thread-4) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=55895}
[junit4] 2> 790416 ERROR (jetty-launcher-1520-thread-4) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 790416 INFO (jetty-launcher-1520-thread-4) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.3
[junit4] 2> 790416 INFO (jetty-launcher-1520-thread-4) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 790416 INFO (jetty-launcher-1520-thread-4) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 790416 INFO (jetty-launcher-1520-thread-4) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-03-02T07:19:22.533Z
[junit4] 2> 790427 INFO (jetty-launcher-1520-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 790432 INFO (jetty-launcher-1520-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 790445 INFO (jetty-launcher-1520-thread-4) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 790447 INFO (jetty-launcher-1520-thread-2) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 790448 INFO (jetty-launcher-1520-thread-3) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 790450 INFO (jetty-launcher-1520-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 790451 INFO (jetty-launcher-1520-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:57579/solr
[junit4] 2> 790451 INFO (jetty-launcher-1520-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:57579/solr
[junit4] 2> 790453 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 0x161e59462160004, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 790455 INFO (jetty-launcher-1520-thread-4) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 790455 INFO (jetty-launcher-1520-thread-4) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:57579/solr
[junit4] 2> 790462 INFO (jetty-launcher-1520-thread-3) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 790469 INFO (jetty-launcher-1520-thread-3) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:57579/solr
[junit4] 2> 790490 INFO (jetty-launcher-1520-thread-1) [n:127.0.0.1:54009_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 790490 INFO (jetty-launcher-1520-thread-1) [n:127.0.0.1:54009_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:54009_solr
[junit4] 2> 790491 INFO (jetty-launcher-1520-thread-1) [n:127.0.0.1:54009_solr ] o.a.s.c.Overseer Overseer (id=99613092242391048-127.0.0.1:54009_solr-n_0000000000) starting
[junit4] 2> 790501 INFO (jetty-launcher-1520-thread-2) [n:127.0.0.1:57341_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 790502 INFO (jetty-launcher-1520-thread-2) [n:127.0.0.1:57341_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57341_solr
[junit4] 2> 790516 INFO (zkCallback-1536-thread-1-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 790516 INFO (zkCallback-1539-thread-1-processing-n:127.0.0.1:57341_solr) [n:127.0.0.1:57341_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 790518 INFO (jetty-launcher-1520-thread-4) [n:127.0.0.1:55895_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 790520 INFO (jetty-launcher-1520-thread-4) [n:127.0.0.1:55895_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 790521 INFO (jetty-launcher-1520-thread-4) [n:127.0.0.1:55895_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55895_solr
[junit4] 2> 790522 INFO (zkCallback-1539-thread-1-processing-n:127.0.0.1:57341_solr) [n:127.0.0.1:57341_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 790522 INFO (zkCallback-1536-thread-1-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 790542 INFO (jetty-launcher-1520-thread-1) [n:127.0.0.1:54009_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54009_solr
[junit4] 2> 790547 INFO (zkCallback-1539-thread-1-processing-n:127.0.0.1:57341_solr) [n:127.0.0.1:57341_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 790552 INFO (zkCallback-1538-thread-1-processing-n:127.0.0.1:55895_solr) [n:127.0.0.1:55895_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (3)
[junit4] 2> 790557 INFO (zkCallback-1536-thread-2-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 790560 INFO (jetty-launcher-1520-thread-3) [n:127.0.0.1:54753_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3)
[junit4] 2> 790561 INFO (jetty-launcher-1520-thread-3) [n:127.0.0.1:54753_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 790563 INFO (jetty-launcher-1520-thread-3) [n:127.0.0.1:54753_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54753_solr
[junit4] 2> 790564 INFO (zkCallback-1539-thread-1-processing-n:127.0.0.1:57341_solr) [n:127.0.0.1:57341_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 790564 INFO (zkCallback-1538-thread-1-processing-n:127.0.0.1:55895_solr) [n:127.0.0.1:55895_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 790570 INFO (zkCallback-1536-thread-2-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 790577 INFO (zkCallback-1545-thread-1-processing-n:127.0.0.1:54753_solr) [n:127.0.0.1:54753_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 790658 INFO (jetty-launcher-1520-thread-1) [n:127.0.0.1:54009_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-001/node1/.
[junit4] 2> 790662 INFO (jetty-launcher-1520-thread-4) [n:127.0.0.1:55895_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-001/node4/.
[junit4] 2> 790676 INFO (jetty-launcher-1520-thread-3) [n:127.0.0.1:54753_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-001/node3/.
[junit4] 2> 790701 INFO (jetty-launcher-1520-thread-2) [n:127.0.0.1:57341_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-001/node2/.
[junit4] 2> 790716 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 790717 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:57579/solr ready
[junit4] 2> 790747 INFO (TEST-CollectionsAPIDistributedZkTest.testTooManyReplicas-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testTooManyReplicas
[junit4] 2> 790748 INFO (TEST-CollectionsAPIDistributedZkTest.testTooManyReplicas-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 790817 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=10&collection.configName=conf&name=collection&action=CREATE&numShards=2&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 790819 INFO (OverseerThreadFactory-4139-thread-1-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.CreateCollectionCmd Create collection collection
[junit4] 2> 790819 WARN (OverseerThreadFactory-4139-thread-1-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.CreateCollectionCmd Specified replicationFactor of 10 on collection collection is higher than or equal to the number of Solr instances currently live or live and part of your createNodeSet(4). It's unusual to run two replica of the same slice on the same Solr-instance.
[junit4] 2> 790820 ERROR (OverseerThreadFactory-4139-thread-1-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.OverseerCollectionMessageHandler Collection: collection operation: create failed:org.apache.solr.common.SolrException: Cannot create collection collection. Value of maxShardsPerNode is 1, and the number of nodes currently live or live and part of your createNodeSet is 4. This allows a maximum of 4 to be created. Value of numShards is 2 and value of replicationFactor is 10. This requires 20 shards to be created (higher than the allowed number)
[junit4] 2> at org.apache.solr.cloud.CreateCollectionCmd.call(CreateCollectionCmd.java:155)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionMessageHandler.processMessage(OverseerCollectionMessageHandler.java:226)
[junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor$Runner.run(OverseerTaskProcessor.java:464)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2>
[junit4] 2> 790823 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=10&collection.configName=conf&name=collection&action=CREATE&numShards=2&wt=javabin&version=2} status=400 QTime=5
[junit4] 2> 790843 INFO (TEST-CollectionsAPIDistributedZkTest.testTooManyReplicas-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testTooManyReplicas
[junit4] 2> 790864 INFO (TEST-CollectionsAPIDistributedZkTest.deletePartiallyCreatedCollection-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting deletePartiallyCreatedCollection
[junit4] 2> 790865 INFO (TEST-CollectionsAPIDistributedZkTest.deletePartiallyCreatedCollection-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 790868 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CoreAdminOperation core create command dataDir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-002&collection.configName=conf&name=halfdeletedcollection_shard1_replica1&action=CREATE&numShards=2&collection=halfdeletedcollection&wt=javabin&version=2
[junit4] 2> 790869 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 790870 INFO (OverseerStateUpdate-99613092242391048-127.0.0.1:54009_solr-n_0000000000) [n:127.0.0.1:54009_solr ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 791878 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.3
[junit4] 2> 791885 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.s.IndexSchema [halfdeletedcollection_shard1_replica1] Schema name=minimal
[junit4] 2> 791887 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 791887 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.CoreContainer Creating SolrCore 'halfdeletedcollection_shard1_replica1' using configuration from collection halfdeletedcollection, trusted=true
[junit4] 2> 791888 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 791888 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.SolrCore [[halfdeletedcollection_shard1_replica1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-001/node2/halfdeletedcollection_shard1_replica1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-002/]
[junit4] 2> 791921 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 791921 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 791922 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 791922 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 791923 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@567f395e[halfdeletedcollection_shard1_replica1] main]
[junit4] 2> 791924 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 791924 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 791924 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 791924 INFO (searcherExecutor-4148-thread-1-processing-n:127.0.0.1:57341_solr x:halfdeletedcollection_shard1_replica1 c:halfdeletedcollection) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.SolrCore [halfdeletedcollection_shard1_replica1] Registered new searcher Searcher@567f395e[halfdeletedcollection_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 791924 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1593809477609455616
[junit4] 2> 791930 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 791930 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 791930 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:57341/solr/halfdeletedcollection_shard1_replica1/
[junit4] 2> 791930 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 791930 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.SyncStrategy https://127.0.0.1:57341/solr/halfdeletedcollection_shard1_replica1/ has no replicas
[junit4] 2> 791930 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 791933 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:57341/solr/halfdeletedcollection_shard1_replica1/ shard2
[junit4] 2> 792084 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 792086 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr c:halfdeletedcollection x:halfdeletedcollection_shard1_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={dataDir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-002&collection.configName=conf&name=halfdeletedcollection_shard1_replica1&action=CREATE&numShards=2&collection=halfdeletedcollection&wt=javabin&version=2} status=0 QTime=1218
[junit4] 2> 792088 INFO (qtp1492280155-9768) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=halfdeletedcollection&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 792090 INFO (OverseerThreadFactory-4139-thread-2-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true
[junit4] 2> 792090 INFO (OverseerCollectionConfigSetProcessor-99613092242391048-127.0.0.1:54009_solr-n_0000000000) [n:127.0.0.1:54009_solr ] 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> 792094 INFO (qtp1492280155-9773) [n:127.0.0.1:57341_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.halfdeletedcollection.shard1.replica1
[junit4] 2> 792094 INFO (qtp1492280155-9773) [n:127.0.0.1:57341_solr ] o.a.s.c.SolrCore [halfdeletedcollection_shard1_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@11c57125
[junit4] 2> 792095 INFO (qtp1492280155-9773) [n:127.0.0.1:57341_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.halfdeletedcollection.shard1.replica1
[junit4] 2> 792096 INFO (qtp1492280155-9773) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=halfdeletedcollection_shard1_replica1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 792799 INFO (qtp1492280155-9768) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=halfdeletedcollection&action=DELETE&wt=javabin&version=2} status=0 QTime=710
[junit4] 2> 792801 INFO (qtp1492280155-9771) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 792801 INFO (qtp1492280155-9771) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 792802 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf&name=halfdeletedcollection&action=CREATE&numShards=2&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 792804 INFO (OverseerThreadFactory-4139-thread-3-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.CreateCollectionCmd Create collection halfdeletedcollection
[junit4] 2> 792804 INFO (OverseerCollectionConfigSetProcessor-99613092242391048-127.0.0.1:54009_solr-n_0000000000) [n:127.0.0.1:54009_solr ] 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> 793016 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=halfdeletedcollection_shard1_replica1&action=CREATE&numShards=2&collection=halfdeletedcollection&shard=shard1&wt=javabin&version=2
[junit4] 2> 793066 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=halfdeletedcollection_shard2_replica1&action=CREATE&numShards=2&collection=halfdeletedcollection&shard=shard2&wt=javabin&version=2
[junit4] 2> 793066 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 793170 INFO (zkCallback-1539-thread-1-processing-n:127.0.0.1:57341_solr) [n:127.0.0.1:57341_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfdeletedcollection/state.json] for collection [halfdeletedcollection] has occurred - updating... (live nodes size: [4])
[junit4] 2> 793170 INFO (zkCallback-1536-thread-2-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfdeletedcollection/state.json] for collection [halfdeletedcollection] has occurred - updating... (live nodes size: [4])
[junit4] 2> 794026 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.3
[junit4] 2> 794034 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.s.IndexSchema [halfdeletedcollection_shard1_replica1] Schema name=minimal
[junit4] 2> 794036 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 794036 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.CoreContainer Creating SolrCore 'halfdeletedcollection_shard1_replica1' using configuration from collection halfdeletedcollection, trusted=true
[junit4] 2> 794037 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 794037 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.SolrCore [[halfdeletedcollection_shard1_replica1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-001/node2/halfdeletedcollection_shard1_replica1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-001/node2/./halfdeletedcollection_shard1_replica1/data/]
[junit4] 2> 794080 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.3
[junit4] 2> 794088 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.s.IndexSchema [halfdeletedcollection_shard2_replica1] Schema name=minimal
[junit4] 2> 794090 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 794091 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.CoreContainer Creating SolrCore 'halfdeletedcollection_shard2_replica1' using configuration from collection halfdeletedcollection, trusted=true
[junit4] 2> 794091 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 794091 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.SolrCore [[halfdeletedcollection_shard2_replica1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-001/node1/halfdeletedcollection_shard2_replica1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001/tempDir-001/node1/./halfdeletedcollection_shard2_replica1/data/]
[junit4] 2> 794099 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 794099 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 794100 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 794100 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 794100 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1229762b[halfdeletedcollection_shard1_replica1] main]
[junit4] 2> 794101 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 794101 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 794102 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 794102 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1593809479893254144
[junit4] 2> 794103 INFO (searcherExecutor-4153-thread-1-processing-n:127.0.0.1:57341_solr x:halfdeletedcollection_shard1_replica1 s:shard1 c:halfdeletedcollection) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.SolrCore [halfdeletedcollection_shard1_replica1] Registered new searcher Searcher@1229762b[halfdeletedcollection_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 794107 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 794107 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 794107 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:57341/solr/halfdeletedcollection_shard1_replica1/
[junit4] 2> 794107 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 794107 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.SyncStrategy https://127.0.0.1:57341/solr/halfdeletedcollection_shard1_replica1/ has no replicas
[junit4] 2> 794107 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 794111 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:57341/solr/halfdeletedcollection_shard1_replica1/ shard1
[junit4] 2> 794127 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 794127 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 794138 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 794138 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 794138 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@61a2b9d4[halfdeletedcollection_shard2_replica1] main]
[junit4] 2> 794139 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 794140 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 794140 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 794140 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1593809479933100032
[junit4] 2> 794140 INFO (searcherExecutor-4154-thread-1-processing-n:127.0.0.1:54009_solr x:halfdeletedcollection_shard2_replica1 s:shard2 c:halfdeletedcollection) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.SolrCore [halfdeletedcollection_shard2_replica1] Registered new searcher Searcher@61a2b9d4[halfdeletedcollection_shard2_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 794147 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 794147 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 794147 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:54009/solr/halfdeletedcollection_shard2_replica1/
[junit4] 2> 794147 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 794147 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.SyncStrategy https://127.0.0.1:54009/solr/halfdeletedcollection_shard2_replica1/ has no replicas
[junit4] 2> 794147 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 794150 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:54009/solr/halfdeletedcollection_shard2_replica1/ shard2
[junit4] 2> 794250 INFO (zkCallback-1539-thread-1-processing-n:127.0.0.1:57341_solr) [n:127.0.0.1:57341_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfdeletedcollection/state.json] for collection [halfdeletedcollection] has occurred - updating... (live nodes size: [4])
[junit4] 2> 794251 INFO (zkCallback-1536-thread-2-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfdeletedcollection/state.json] for collection [halfdeletedcollection] has occurred - updating... (live nodes size: [4])
[junit4] 2> 794262 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 794266 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr c:halfdeletedcollection s:shard1 x:halfdeletedcollection_shard1_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=halfdeletedcollection_shard1_replica1&action=CREATE&numShards=2&collection=halfdeletedcollection&shard=shard1&wt=javabin&version=2} status=0 QTime=1250
[junit4] 2> 794300 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 794303 INFO (qtp1003230050-9746) [n:127.0.0.1:54009_solr c:halfdeletedcollection s:shard2 x:halfdeletedcollection_shard2_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=halfdeletedcollection_shard2_replica1&action=CREATE&numShards=2&collection=halfdeletedcollection&shard=shard2&wt=javabin&version=2} status=0 QTime=1236
[junit4] 2> 794304 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
[junit4] 2> 794404 INFO (zkCallback-1536-thread-2-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfdeletedcollection/state.json] for collection [halfdeletedcollection] has occurred - updating... (live nodes size: [4])
[junit4] 2> 794404 INFO (zkCallback-1539-thread-1-processing-n:127.0.0.1:57341_solr) [n:127.0.0.1:57341_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/halfdeletedcollection/state.json] for collection [halfdeletedcollection] has occurred - updating... (live nodes size: [4])
[junit4] 2> 794805 INFO (OverseerCollectionConfigSetProcessor-99613092242391048-127.0.0.1:54009_solr-n_0000000000) [n:127.0.0.1:54009_solr ] 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> 795304 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf&name=halfdeletedcollection&action=CREATE&numShards=2&wt=javabin&version=2} status=0 QTime=2501
[junit4] 2> 795306 INFO (qtp1492280155-9769) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 795307 INFO (qtp1492280155-9769) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 795307 INFO (TEST-CollectionsAPIDistributedZkTest.deletePartiallyCreatedCollection-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending deletePartiallyCreatedCollection
[junit4] 2> 795327 INFO (TEST-CollectionsAPIDistributedZkTest.testCreateNodeSet-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateNodeSet
[junit4] 2> 795328 INFO (TEST-CollectionsAPIDistributedZkTest.testCreateNodeSet-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 795330 INFO (qtp1492280155-9773) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=halfdeletedcollection&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 795332 INFO (OverseerThreadFactory-4139-thread-4-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true
[junit4] 2> 795334 INFO (qtp1492280155-9772) [n:127.0.0.1:57341_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.halfdeletedcollection.shard1.replica1
[junit4] 2> 795334 INFO (qtp1492280155-9772) [n:127.0.0.1:57341_solr ] o.a.s.c.SolrCore [halfdeletedcollection_shard1_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@3e755ff3
[junit4] 2> 795335 INFO (qtp1492280155-9772) [n:127.0.0.1:57341_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.halfdeletedcollection.shard1.replica1
[junit4] 2> 795336 INFO (qtp1003230050-9747) [n:127.0.0.1:54009_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.halfdeletedcollection.shard2.replica1
[junit4] 2> 795336 INFO (qtp1003230050-9747) [n:127.0.0.1:54009_solr ] o.a.s.c.SolrCore [halfdeletedcollection_shard2_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@1bd5f22d
[junit4] 2> 795338 INFO (qtp1492280155-9772) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=halfdeletedcollection_shard1_replica1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=4
[junit4] 2> 795339 INFO (qtp1003230050-9747) [n:127.0.0.1:54009_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.halfdeletedcollection.shard2.replica1
[junit4] 2> 795342 INFO (qtp1003230050-9747) [n:127.0.0.1:54009_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=halfdeletedcollection_shard2_replica1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=6
[junit4] 2> 796046 INFO (qtp1492280155-9773) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=halfdeletedcollection&action=DELETE&wt=javabin&version=2} status=0 QTime=715
[junit4] 2> 796048 INFO (qtp1492280155-9768) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf&name=nodeset_collection&action=CREATE&numShards=2&createNodeSet=https://127.0.0.1:54753/solr,https://127.0.0.1:55895/solr&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 796049 INFO (OverseerThreadFactory-4139-thread-5-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.CreateCollectionCmd Create collection nodeset_collection
[junit4] 2> 796050 WARN (OverseerThreadFactory-4139-thread-5-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.CreateCollectionCmd It is unusual to create a collection (nodeset_collection) without cores.
[junit4] 2> 796050 INFO (OverseerCollectionConfigSetProcessor-99613092242391048-127.0.0.1:54009_solr-n_0000000000) [n:127.0.0.1:54009_solr ] 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> 796258 INFO (qtp1492280155-9768) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
[junit4] 2> 796258 INFO (qtp1492280155-9768) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf&name=nodeset_collection&action=CREATE&numShards=2&createNodeSet=https://127.0.0.1:54753/solr,https://127.0.0.1:55895/solr&wt=javabin&version=2} status=0 QTime=210
[junit4] 2> 796259 INFO (TEST-CollectionsAPIDistributedZkTest.testCreateNodeSet-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testCreateNodeSet
[junit4] 2> 796293 INFO (TEST-CollectionsAPIDistributedZkTest.deleteCollectionRemovesStaleZkCollectionsNode-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting deleteCollectionRemovesStaleZkCollectionsNode
[junit4] 2> 796294 INFO (TEST-CollectionsAPIDistributedZkTest.deleteCollectionRemovesStaleZkCollectionsNode-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 796296 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=nodeset_collection&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 796298 INFO (OverseerThreadFactory-4139-thread-5-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true
[junit4] 2> 796298 INFO (OverseerCollectionConfigSetProcessor-99613092242391048-127.0.0.1:54009_solr-n_0000000000) [n:127.0.0.1:54009_solr ] 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> 797001 INFO (qtp1492280155-9774) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=nodeset_collection&action=DELETE&wt=javabin&version=2} status=0 QTime=704
[junit4] 2> 797005 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=out_of_sync_collection&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 797011 INFO (OverseerCollectionConfigSetProcessor-99613092242391048-127.0.0.1:54009_solr-n_0000000000) [n:127.0.0.1:54009_solr ] 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> 797014 INFO (qtp1492280155-9775) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=out_of_sync_collection&action=DELETE&wt=javabin&version=2} status=0 QTime=9
[junit4] 2> 797016 INFO (qtp1492280155-9769) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 797016 INFO (qtp1492280155-9769) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 797016 INFO (TEST-CollectionsAPIDistributedZkTest.deleteCollectionRemovesStaleZkCollectionsNode-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending deleteCollectionRemovesStaleZkCollectionsNode
[junit4] 2> 797045 INFO (TEST-CollectionsAPIDistributedZkTest.testMissingNumShards-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testMissingNumShards
[junit4] 2> 797046 INFO (TEST-CollectionsAPIDistributedZkTest.testMissingNumShards-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 797049 INFO (qtp1492280155-9769) [n:127.0.0.1:57341_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=10&collection.configName=conf&name=acollection&action=CREATE&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 797051 INFO (OverseerThreadFactory-4139-thread-5-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.CreateCollectionCmd Create collection acollection
[junit4] 2> 797051 ERROR (OverseerThreadFactory-4139-thread-5-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.OverseerCollectionMessageHandler Collection: acollection operation: create failed:org.apache.solr.common.SolrException: numShards is a required param (when using CompositeId router).
[junit4] 2> at org.apache.solr.cloud.CreateCollectionCmd.call(CreateCollectionCmd.java:112)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionMessageHandler.processMessage(OverseerCollectionMessageHandler.java:226)
[junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor$Runner.run(OverseerTaskProcessor.java:464)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2>
[junit4] 2> 797052 INFO (OverseerCollectionConfigSetProcessor-99613092242391048-127.0.0.1:54009_solr-n_0000000000) [n:127.0.0.1:54009_solr ] 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> 797059 INFO (qtp1492280155-9769) [n:127.0.0.1:57341_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=10&collection.configName=conf&name=acollection&action=CREATE&wt=javabin&version=2} status=400 QTime=10
[junit4] 2> 797064 INFO (TEST-CollectionsAPIDistributedZkTest.testMissingNumShards-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testMissingNumShards
[junit4] 2> 797089 INFO (TEST-CollectionsAPIDistributedZkTest.testBadActionNames-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testBadActionNames
[junit4] 2> 797090 INFO (TEST-CollectionsAPIDistributedZkTest.testBadActionNames-seed#[CB4E4B01BDAA51DA]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 797093 ERROR (qtp1492280155-9773) [n:127.0.0.1:57341_solr ] o.a.s.h.RequestHandlerBase org.apache.solr.common.SolrException: Unknown action: BADACTION
[junit4] 2> at org.apache.solr.handler.admin.CollectionsHandler.handleRequestBody(CollectionsHandler.java:210)
[junit4] 2> at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:173)
[junit4] 2> at org.apache.solr.servlet.HttpSolrCall.handleAdmin(HttpSolrCall.java:748)
[junit4] 2> at org.apache.solr.servlet.HttpSolrCall.handleAdminRequest(HttpSolrCall.java:729)
[junit4] 2> at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:510)
[...truncated too long message...]
re@5a0f1cd6
[junit4] 2> 880368 INFO (coreCloseExecutor-4410-thread-1) [n:127.0.0.1:55895_solr c:nodes_used_collection s:shard1 r:core_node1 x:nodes_used_collection_shard1_replica2] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.nodes_used_collection.shard1.replica2
[junit4] 2> 880368 INFO (coreCloseExecutor-4409-thread-1) [n:127.0.0.1:54753_solr c:nodes_used_collection s:shard2 r:core_node2 x:nodes_used_collection_shard2_replica2] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.nodes_used_collection.shard2.replica2
[junit4] 2> 880369 INFO (zkCallback-1536-thread-2-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3)
[junit4] 2> 880369 INFO (zkCallback-1545-thread-2-processing-n:127.0.0.1:54753_solr) [n:127.0.0.1:54753_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3)
[junit4] 2> 880369 INFO (zkCallback-1538-thread-1-processing-n:127.0.0.1:55895_solr) [n:127.0.0.1:55895_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (3)
[junit4] 2> 880372 INFO (zkCallback-1536-thread-2-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (2)
[junit4] 2> 880383 INFO (coreCloseExecutor-4413-thread-1) [n:127.0.0.1:54009_solr c:nodes_used_collection s:shard2 r:core_node3 x:nodes_used_collection_shard2_replica1] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.nodes_used_collection.shard2.replica1
[junit4] 2> 880384 INFO (zkCallback-1536-thread-2-processing-n:127.0.0.1:54009_solr) [n:127.0.0.1:54009_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 880388 INFO (jetty-closer-1521-thread-1) [ ] o.a.s.c.Overseer Overseer (id=99613092242391048-127.0.0.1:54009_solr-n_0000000000) closing
[junit4] 2> 880388 INFO (OverseerStateUpdate-99613092242391048-127.0.0.1:54009_solr-n_0000000000) [n:127.0.0.1:54009_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:54009_solr
[junit4] 2> 880389 INFO (jetty-closer-1521-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@6abe088a{/solr,null,UNAVAILABLE}
[junit4] 2> 880390 WARN (zkCallback-1545-thread-3-processing-n:127.0.0.1:54753_solr) [n:127.0.0.1:54753_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 880390 INFO (jetty-closer-1521-thread-3) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@f86aed7{/solr,null,UNAVAILABLE}
[junit4] 2> 881869 WARN (zkCallback-1539-thread-1-processing-n:127.0.0.1:57341_solr) [n:127.0.0.1:57341_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 881869 INFO (jetty-closer-1521-thread-4) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@26485f55{/solr,null,UNAVAILABLE}
[junit4] 2> 881872 WARN (zkCallback-1538-thread-1-processing-n:127.0.0.1:55895_solr) [n:127.0.0.1:55895_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 881872 INFO (jetty-closer-1521-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@77ea2124{/solr,null,UNAVAILABLE}
[junit4] 2> 881873 ERROR (SUITE-CollectionsAPIDistributedZkTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 881873 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:57579 57579
[junit4] 2> 881971 INFO (Thread-3007) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:57579 57579
[junit4] 2> 881972 WARN (Thread-3007) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 25 /solr/aliases.json
[junit4] 2> 23 /solr/configs/conf
[junit4] 2> 5 /solr/configs/conf2
[junit4] 2> 4 /solr/security.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 289 /solr/clusterstate.json
[junit4] 2> 25 /solr/clusterprops.json
[junit4] 2> 5 /solr/collections/awhollynewcollection_0/state.json
[junit4] 2> 4 /solr/collections/nodes_used_collection/state.json
[junit4] 2> 4 /solr/collections/addReplicaColl/state.json
[junit4] 2> 4 /solr/collections/reloaded_collection/state.json
[junit4] 2> 3 /solr/collections/acollectionafterbaddelete/state.json
[junit4] 2> 3 /solr/collections/addReplicaColl/leader_elect/shard1/election/99613092242391049-core_node1-n_0000000000
[junit4] 2> 2 /solr/overseer_elect/election/99613092242391048-127.0.0.1:54009_solr-n_0000000000
[junit4] 2> 2 /solr/collections/onlyinzk/state.json
[junit4] 2> 2 /solr/collections/awhollynewcollection_0/leader_elect/shard1/election/99613092242391049-core_node18-n_0000000001
[junit4] 2> 2 /solr/collections/awhollynewcollection_0/leader_elect/shard1/election/99613092242391048-core_node3-n_0000000000
[junit4] 2> 2 /solr/collections/awhollynewcollection_0/leader_elect/shard2/election/99613092242391049-core_node2-n_0000000000
[junit4] 2> 2 /solr/collections/awhollynewcollection_0/leader_elect/shard3/election/99613092242391048-core_node8-n_0000000000
[junit4] 2> 2 /solr/collections/halfdeletedcollection/state.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 488 /solr/collections
[junit4] 2> 25 /solr/live_nodes
[junit4] 2>
[junit4] 2> 881972 INFO (SUITE-CollectionsAPIDistributedZkTest-seed#[CB4E4B01BDAA51DA]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.6/solr/build/solr-core/test/J2/temp/solr.cloud.CollectionsAPIDistributedZkTest_CB4E4B01BDAA51DA-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene62): {_version_=TestBloomFilteredLucenePostings(BloomFilteringPostingsFormat(Lucene50(blocksize=128))), id=PostingsFormat(name=Asserting)}, docValues:{}, maxPointsInLeafNode=1672, maxMBSortInHeap=7.1000094344028035, sim=RandomSimilarity(queryNorm=true,coord=no): {}, locale=ar-JO, timezone=Atlantic/Cape_Verde
[junit4] 2> NOTE: Linux 3.13.0-88-generic amd64/Oracle Corporation 1.8.0_144 (64-bit)/cpus=4,threads=1,free=103048992,total=516947968
[junit4] 2> NOTE: All tests run in this JVM: [QueryParsingTest, TermVectorComponentDistributedTest, TestTestInjection, TestReload, TestRandomRequestDistribution, TestUseDocValuesAsStored2, SolrCoreMetricManagerTest, TestCoreDiscovery, SolrCoreCheckLockOnStartupTest, CdcrReplicationDistributedZkTest, TestDynamicLoading, PrimUtilsTest, SuggesterTSTTest, TestCollationField, TestReqParamsAPI, PingRequestHandlerTest, DistributedQueryComponentOptimizationTest, TestFieldCacheWithThreads, TestExclusionRuleCollectionAccess, TestCloudPivotFacet, HdfsDirectoryTest, TestUnifiedSolrHighlighter, TestSolrCloudWithDelegationTokens, BlockCacheTest, NoCacheHeaderTest, TestJsonFacetRefinement, TestFieldTypeResource, LukeRequestHandlerTest, TestSolrCoreSnapshots, TestPhraseSuggestions, RequestHandlersTest, SharedFSAutoReplicaFailoverUtilsTest, TestCustomSort, XmlUpdateRequestHandlerTest, TestCloudManagedSchema, DistributedFacetPivotLargeTest, PKIAuthenticationIntegrationTest, TestSolrFieldCacheMBean, TestSystemCollAutoCreate, LegacyCloudClusterPropTest, CursorMarkTest, OutOfBoxZkACLAndCredentialsProvidersTest, TestLMJelinekMercerSimilarityFactory, TestDFRSimilarityFactory, FullHLLTest, HdfsWriteToMultipleCollectionsTest, TimeZoneUtilsTest, MoveReplicaTest, TestLFUCache, PrimitiveFieldTypeTest, SolrPluginUtilsTest, TestIntervalFaceting, TestOrdValues, TestObjectReleaseTracker, OverseerModifyCollectionTest, TestConfig, HdfsCollectionsAPIDistributedZkTest, TestRuleBasedAuthorizationPlugin, RestartWhileUpdatingTest, FullSolrCloudDistribCmdsTest, AutoCommitTest, StatelessScriptUpdateProcessorFactoryTest, MetricsHandlerTest, TestCustomDocTransformer, HdfsRecoveryZkTest, BlockJoinFacetDistribTest, TestFileDictionaryLookup, TestSegmentSorting, TestNoOpRegenerator, ResponseLogComponentTest, TestConfigSets, TestSmileRequest, TestTolerantUpdateProcessorCloud, BinaryUpdateRequestHandlerTest, SolrJmxReporterCloudTest, TestTrieFacet, TestInitParams, TestEmbeddedSolrServerSchemaAPI, TestDistributedMissingSort, FieldAnalysisRequestHandlerTest, ActionThrottleTest, ZkStateReaderTest, DeleteShardTest, TestSolrDynamicMBean, SegmentsInfoRequestHandlerTest, StatsComponentTest, TestIndexingPerformance, SimpleFacetsTest, TestRequestForwarding, CloneFieldUpdateProcessorFactoryTest, TestShardHandlerFactory, SuggesterTest, TestManagedStopFilterFactory, CoreAdminRequestStatusTest, TestCloudDeleteByQuery, BigEndianAscendingWordSerializerTest, TestSubQueryTransformerDistrib, SaslZkACLProviderTest, TestExtendedDismaxParser, SolrTestCaseJ4Test, TestSort, TestStressReorder, TestRecovery, UnloadDistributedZkTest, ParsingFieldUpdateProcessorsTest, HardAutoCommitTest, BadIndexSchemaTest, CurrencyFieldXmlFileTest, AsyncCallRequestStatusResponseTest, TestFieldCache, TestConfigOverlay, BasicDistributedZk2Test, DistributedFacetPivotSmallTest, CloudExitableDirectoryReaderTest, BasicDistributedZkTest, ChaosMonkeySafeLeaderTest, CollectionsAPIDistributedZkTest]
[junit4] Completed [287/714 (2!)] on J2 in 91.72s, 20 tests, 1 failure <<< FAILURES!
[...truncated 47667 lines...]