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/02/23 02:24:41 UTC
[JENKINS] Lucene-Solr-Tests-7.x - Build # 439 - Unstable
Build: https://builds.apache.org/job/Lucene-Solr-Tests-7.x/439/
2 tests failed.
FAILED: org.apache.solr.cloud.autoscaling.ComputePlanActionTest.testNodeLost
Error Message:
org.apache.solr.common.SolrException:
Stack Trace:
org.apache.solr.common.SolrException: org.apache.solr.common.SolrException:
at __randomizedtesting.SeedInfo.seed([F3984EEA98A4E19C:4C8D80141B4E841A]:0)
at org.apache.solr.common.cloud.rule.ImplicitSnitch.getTags(ImplicitSnitch.java:78)
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider.getNodeValues(SolrClientNodeStateProvider.java:111)
at org.apache.solr.cloud.autoscaling.ComputePlanActionTest.printState(ComputePlanActionTest.java:139)
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:1737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:992)
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:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
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)
Caused by: org.apache.solr.common.SolrException:
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider$AutoScalingSnitch.getRemoteInfo(SolrClientNodeStateProvider.java:250)
at org.apache.solr.common.cloud.rule.ImplicitSnitch.getTags(ImplicitSnitch.java:76)
... 39 more
Caused by: org.apache.solr.client.solrj.SolrServerException: Server refused connection at: https://127.0.0.1:58387/solr
at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:650)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:255)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:244)
at org.apache.solr.client.solrj.SolrClient.request(SolrClient.java:1219)
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider$ClientSnitchCtx.invoke(SolrClientNodeStateProvider.java:292)
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider$AutoScalingSnitch.getRemoteInfo(SolrClientNodeStateProvider.java:227)
... 40 more
Caused by: org.apache.http.conn.HttpHostConnectException: Connect to 127.0.0.1:58387 [/127.0.0.1] failed: Connection refused (Connection refused)
at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:159)
at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:359)
at org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:381)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:237)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56)
at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:542)
... 45 more
Caused by: java.net.ConnectException: Connection refused (Connection refused)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at org.apache.http.conn.ssl.SSLConnectionSocketFactory.connectSocket(SSLConnectionSocketFactory.java:339)
at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:142)
... 55 more
FAILED: org.apache.solr.handler.TestReplicationHandler.doTestIndexAndConfigReplication
Error Message:
Index: 0, Size: 0
Stack Trace:
java.lang.IndexOutOfBoundsException: Index: 0, Size: 0
at __randomizedtesting.SeedInfo.seed([F3984EEA98A4E19C:E7D015BFBBA35C82]:0)
at java.util.ArrayList.rangeCheck(ArrayList.java:653)
at java.util.ArrayList.get(ArrayList.java:429)
at org.apache.solr.handler.TestReplicationHandler.doTestIndexAndConfigReplication(TestReplicationHandler.java:561)
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:1737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984)
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:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
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 13535 lines...]
[junit4] Suite: org.apache.solr.handler.TestReplicationHandler
[junit4] 2> Creating dataDir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/init-core-data-001
[junit4] 2> 1419578 WARN (SUITE-TestReplicationHandler-seed#[F3984EEA98A4E19C]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=123 numCloses=123
[junit4] 2> 1419579 INFO (SUITE-TestReplicationHandler-seed#[F3984EEA98A4E19C]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true
[junit4] 2> 1419580 INFO (SUITE-TestReplicationHandler-seed#[F3984EEA98A4E19C]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.SolrTestCaseJ4$SuppressSSL(bugUrl=None)
[junit4] 2> 1419580 INFO (SUITE-TestReplicationHandler-seed#[F3984EEA98A4E19C]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> 1419583 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.SolrTestCaseJ4 ###Starting doTestReplicateAfterCoreReload
[junit4] 2> 1419584 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/collection1
[junit4] 2> 1419587 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T21:27:37Z, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
[junit4] 2> 1419589 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1419589 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1419589 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session Scavenging every 600000ms
[junit4] 2> 1419590 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@566443e8{/solr,null,AVAILABLE}
[junit4] 2> 1419590 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@601659a1{HTTP/1.1,[http/1.1]}{127.0.0.1:34211}
[junit4] 2> 1419591 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.Server Started @1422090ms
[junit4] 2> 1419591 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/collection1/data, hostContext=/solr, hostPort=34211}
[junit4] 2> 1419591 ERROR (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1419591 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 1419591 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 1419591 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1419591 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-02-23T01:43:51.283Z
[junit4] 2> 1419592 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/solr.xml
[junit4] 2> 1419597 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored
[junit4] 2> 1419597 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored
[junit4] 2> 1419598 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 1419628 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419639 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419639 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419641 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/.
[junit4] 2> 1419641 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1419641 INFO (coreLoadExecutor-5642-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 1419655 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0
[junit4] 2> 1419663 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1419664 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
[junit4] 2> 1419664 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/./collection1, trusted=true
[junit4] 2> 1419665 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1' (registry 'solr.core.collection1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419665 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 1419665 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/./collection1/data/]
[junit4] 2> 1419666 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=28, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 1419703 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1419703 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1419703 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=41, maxMergeAtOnceExplicit=17, maxMergedSegmentMB=1.4189453125, floorSegmentMB=0.6982421875, forceMergeDeletesPctAllowed=12.451018689253155, segmentsPerTier=49.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.15188338868596302
[junit4] 2> 1419704 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@38b7c2b0[collection1] main]
[junit4] 2> 1419704 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/collection1/conf
[junit4] 2> 1419705 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Replication enabled for following config files: schema.xml,xslt/dummy.xsl
[junit4] 2> 1419705 INFO (coreLoadExecutor-5642-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 1419707 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/collection1
[junit4] 2> 1419708 INFO (searcherExecutor-5643-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@38b7c2b0[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1419713 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T21:27:37Z, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
[junit4] 2> 1419714 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1419714 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1419714 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session Scavenging every 660000ms
[junit4] 2> 1419714 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@66e9e1da{/solr,null,AVAILABLE}
[junit4] 2> 1419715 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@284ba332{HTTP/1.1,[http/1.1]}{127.0.0.1:60244}
[junit4] 2> 1419715 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.Server Started @1422214ms
[junit4] 2> 1419715 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/collection1/data, hostContext=/solr, hostPort=60244}
[junit4] 2> 1419715 ERROR (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1419715 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 1419715 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 1419715 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1419715 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-02-23T01:43:51.407Z
[junit4] 2> 1419716 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/solr.xml
[junit4] 2> 1419719 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored
[junit4] 2> 1419719 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored
[junit4] 2> 1419721 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 1419750 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419762 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419762 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419764 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/.
[junit4] 2> 1419764 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1419765 INFO (coreLoadExecutor-5652-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 1419786 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0
[junit4] 2> 1419793 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1419795 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
[junit4] 2> 1419795 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/./collection1, trusted=true
[junit4] 2> 1419795 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1' (registry 'solr.core.collection1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419795 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 1419795 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/./collection1/data/]
[junit4] 2> 1419797 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=28, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 1419834 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1419834 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1419835 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=41, maxMergeAtOnceExplicit=17, maxMergedSegmentMB=1.4189453125, floorSegmentMB=0.6982421875, forceMergeDeletesPctAllowed=12.451018689253155, segmentsPerTier=49.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.15188338868596302
[junit4] 2> 1419835 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@736b4fa0[collection1] main]
[junit4] 2> 1419836 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/collection1/conf
[junit4] 2> 1419837 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Poll scheduled at an interval of 1000ms
[junit4] 2> 1419838 INFO (coreLoadExecutor-5652-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 1419839 INFO (searcherExecutor-5653-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@736b4fa0[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1419840 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@284ba332{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1419841 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1735515961
[junit4] 2> 1419841 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1419841 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@5b2da36c: rootName = null, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@5cfdef5d
[junit4] 2> 1419852 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 1419852 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@595d5916: rootName = null, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@22d2d905
[junit4] 2> 1419857 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 1419857 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@67d501cd: rootName = null, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@56d2b374
[junit4] 2> 1419858 INFO (coreCloseExecutor-5658-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@253ae67c
[junit4] 2> 1419858 INFO (coreCloseExecutor-5658-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1, tag=624617084
[junit4] 2> 1419858 INFO (coreCloseExecutor-5658-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@4f6b2ec3: rootName = null, domain = solr.core.collection1, service url = null, agent id = null] for registry solr.core.collection1 / com.codahale.metrics.MetricRegistry@3f8fd093
[junit4] 2> 1419874 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@66e9e1da{/solr,null,UNAVAILABLE}
[junit4] 2> 1419874 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session Stopped scavenging
[junit4] 2> 1419876 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@601659a1{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1419876 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=2037027305
[junit4] 2> 1419876 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1419876 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@feccf22: rootName = null, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@13b9c57b
[junit4] 2> 1419877 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 1419877 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@29193a57: rootName = null, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@22d2d905
[junit4] 2> 1419879 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 1419879 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@4efdbd9b: rootName = null, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@56d2b374
[junit4] 2> 1419879 INFO (coreCloseExecutor-5660-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@70f220a8
[junit4] 2> 1419879 INFO (coreCloseExecutor-5660-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1, tag=1894916264
[junit4] 2> 1419879 INFO (coreCloseExecutor-5660-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@91b6d77: rootName = null, domain = solr.core.collection1, service url = null, agent id = null] for registry solr.core.collection1 / com.codahale.metrics.MetricRegistry@39bcde48
[junit4] 2> 1419881 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@566443e8{/solr,null,UNAVAILABLE}
[junit4] 2> 1419881 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session Stopped scavenging
[junit4] 2> 1419883 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T21:27:37Z, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
[junit4] 2> 1419884 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1419884 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1419884 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session Scavenging every 660000ms
[junit4] 2> 1419884 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2530af20{/solr,null,AVAILABLE}
[junit4] 2> 1419884 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@68823000{HTTP/1.1,[http/1.1]}{127.0.0.1:39851}
[junit4] 2> 1419884 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.Server Started @1422384ms
[junit4] 2> 1419884 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/collection1/data, hostContext=/solr, hostPort=39851}
[junit4] 2> 1419885 ERROR (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1419885 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 1419885 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 1419885 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1419885 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-02-23T01:43:51.577Z
[junit4] 2> 1419885 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/solr.xml
[junit4] 2> 1419889 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored
[junit4] 2> 1419889 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored
[junit4] 2> 1419890 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 1419920 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419930 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419930 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419932 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/.
[junit4] 2> 1419932 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1419933 INFO (coreLoadExecutor-5667-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 1419948 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0
[junit4] 2> 1419955 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1419957 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
[junit4] 2> 1419957 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/./collection1, trusted=true
[junit4] 2> 1419957 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1' (registry 'solr.core.collection1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1419958 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 1419958 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/./collection1/data/]
[junit4] 2> 1419959 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=28, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 1420002 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1420002 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1420002 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=41, maxMergeAtOnceExplicit=17, maxMergedSegmentMB=1.4189453125, floorSegmentMB=0.6982421875, forceMergeDeletesPctAllowed=12.451018689253155, segmentsPerTier=49.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.15188338868596302
[junit4] 2> 1420003 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@4d62b9ba[collection1] main]
[junit4] 2> 1420003 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/collection1/conf
[junit4] 2> 1420004 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Replication enabled for following config files: schema.xml
[junit4] 2> 1420004 INFO (coreLoadExecutor-5667-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 1420005 INFO (searcherExecutor-5668-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@4d62b9ba[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1420006 INFO (qtp937738785-17804) [ x:collection1] o.a.s.u.DirectUpdateHandler2 [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4] 2> 1420006 INFO (qtp937738785-17804) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={wt=javabin&version=2}{deleteByQuery=*:*} 0 0
[junit4] 2> 1420007 INFO (qtp937738785-17806) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1420007 INFO (qtp937738785-17806) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@496c83a2 commitCommandVersion:0
[junit4] 2> 1420008 INFO (qtp937738785-17806) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@6967ec4[collection1] main]
[junit4] 2> 1420009 INFO (qtp937738785-17806) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1420010 INFO (searcherExecutor-5668-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@6967ec4[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1420011 INFO (qtp937738785-17806) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 3
[junit4] 2> 1420011 INFO (qtp937738785-17808) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=*:*&sort=id+desc&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 1420012 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.h.TestReplicationHandler Waited for 0ms and found 0 docs
[junit4] 2> 1420013 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T21:27:37Z, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
[junit4] 2> 1420014 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1420014 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1420014 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session Scavenging every 660000ms
[junit4] 2> 1420015 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@31c75131{/solr,null,AVAILABLE}
[junit4] 2> 1420015 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@2db34ab1{HTTP/1.1,[http/1.1]}{127.0.0.1:45190}
[junit4] 2> 1420015 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.Server Started @1422515ms
[junit4] 2> 1420015 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/collection1/data, hostContext=/solr, hostPort=45190}
[junit4] 2> 1420016 ERROR (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1420016 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 1420016 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 1420016 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1420016 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-02-23T01:43:51.708Z
[junit4] 2> 1420017 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/solr.xml
[junit4] 2> 1420022 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored
[junit4] 2> 1420022 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored
[junit4] 2> 1420023 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 1420053 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1420066 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1420066 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1420069 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/.
[junit4] 2> 1420069 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1420069 INFO (coreLoadExecutor-5677-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 1420084 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0
[junit4] 2> 1420090 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1420092 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
[junit4] 2> 1420092 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/./collection1, trusted=true
[junit4] 2> 1420092 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1' (registry 'solr.core.collection1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1420093 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 1420093 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/./collection1/data/]
[junit4] 2> 1420094 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=28, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 1420132 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1420132 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1420133 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=41, maxMergeAtOnceExplicit=17, maxMergedSegmentMB=1.4189453125, floorSegmentMB=0.6982421875, forceMergeDeletesPctAllowed=12.451018689253155, segmentsPerTier=49.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.15188338868596302
[junit4] 2> 1420133 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@56186640[collection1] main]
[junit4] 2> 1420134 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-002/collection1/conf
[junit4] 2> 1420135 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Poll scheduled at an interval of 1000ms
[junit4] 2> 1420135 INFO (coreLoadExecutor-5677-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 1420137 INFO (searcherExecutor-5678-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@56186640[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1420138 INFO (qtp1882550244-17822) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=*:*&sort=id+desc&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 1420139 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.h.TestReplicationHandler Waited for 0ms and found 0 docs
[junit4] 2> 1420139 INFO (qtp937738785-17806) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getIndexVersion&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1420139 INFO (qtp937738785-17808) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getCommits&qt=/replication&wt=javabin&version=2&command=commits} status=0 QTime=0
[junit4] 2> 1420156 INFO (qtp937738785-17808) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0
[junit4] 2> 1420176 INFO (qtp937738785-17808) [ ] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1420177 INFO (qtp937738785-17808) [ ] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
[junit4] 2> 1420177 INFO (qtp937738785-17808) [ ] o.a.s.c.CoreContainer Reloading SolrCore 'collection1' using configuration from instancedir /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/./collection1
[junit4] 2> 1420202 INFO (qtp937738785-17808) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1' (registry 'solr.core.collection1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1420202 INFO (qtp937738785-17808) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/./collection1/data/]
[junit4] 2> 1420245 INFO (qtp937738785-17808) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1420245 INFO (qtp937738785-17808) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1420246 INFO (qtp937738785-17808) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@37ab46c2[collection1] main]
[junit4] 2> 1420247 INFO (qtp937738785-17808) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-001/collection1/conf
[junit4] 2> 1420247 INFO (qtp937738785-17808) [ x:collection1] o.a.s.h.ReplicationHandler Replication enabled for following config files: schema.xml
[junit4] 2> 1420247 INFO (qtp937738785-17808) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 1420248 INFO (qtp937738785-17808) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=24, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
[junit4] 2> 1420248 INFO (qtp937738785-17808) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1420251 INFO (searcherExecutor-5683-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@37ab46c2[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1420251 INFO (qtp937738785-17808) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@142e2a90[collection1] main]
[junit4] 2> 1420251 INFO (qtp937738785-17808) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@4d01bd49
[junit4] 2> 1420251 INFO (qtp937738785-17808) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1, tag=1291959625
[junit4] 2> 1420251 INFO (qtp937738785-17808) [ x:collection1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@1568b415: rootName = null, domain = solr.core.collection1, service url = null, agent id = null] for registry solr.core.collection1 / com.codahale.metrics.MetricRegistry@7f032369
[junit4] 2> 1420253 INFO (searcherExecutor-5683-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@142e2a90[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1420259 INFO (qtp937738785-17808) [ x:collection1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={core=collection1&qt=/admin/cores&action=reload&wt=javabin&version=2} status=0 QTime=117
[junit4] 2> 1420260 INFO (qtp937738785-17806) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getIndexVersion&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1420261 INFO (qtp937738785-17808) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getCommits&qt=/replication&wt=javabin&version=2&command=commits} status=0 QTime=0
[junit4] 2> 1420262 INFO (qtp937738785-17806) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[10]} 0 0
[junit4] 2> 1420262 INFO (qtp937738785-17808) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[20]} 0 0
[junit4] 2> 1420263 INFO (qtp937738785-17806) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1420263 INFO (qtp937738785-17806) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@66b9818b commitCommandVersion:0
[junit4] 2> 1420266 INFO (qtp937738785-17806) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@4a0c5ba3[collection1] main]
[junit4] 2> 1420266 INFO (qtp937738785-17806) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1420268 INFO (searcherExecutor-5683-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@4a0c5ba3[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.3.0):c2)))}
[junit4] 2> 1420268 INFO (qtp937738785-17806) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 5
[junit4] 2> 1420269 INFO (qtp937738785-17808) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=*:*&sort=id+desc&wt=javabin&version=2} hits=2 status=0 QTime=0
[junit4] 2> 1420270 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.h.TestReplicationHandler Waited for 0ms and found 2 docs
[junit4] 2> 1420270 INFO (qtp1882550244-17824) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=*:*&sort=id+desc&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 1420270 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.h.TestReplicationHandler Waiting for 2 docs
[junit4] 2> 1420275 INFO (qtp937738785-17808) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1420275 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Master's generation: 3
[junit4] 2> 1420275 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Master's version: 1519350231955
[junit4] 2> 1420275 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 1420275 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Slave's version: 0
[junit4] 2> 1420275 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Starting replication process
[junit4] 2> 1420277 INFO (qtp937738785-17806) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&tlogFiles=false&wt=javabin&version=2&command=filelist} status=0 QTime=1
[junit4] 2> 1420277 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Number of files in latest index in master: 4
[junit4] 2> 1420278 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=19, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.21187294817522995]
[junit4] 2> 1420278 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1420278 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Starting download (fullCopy=false) to MockDirectoryWrapper(RAMDirectory@53b13d69 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@4fb1e300)
[junit4] 2> 1420278 INFO (qtp937738785-17808) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_0.cfe&checksum=true&compression=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1420280 INFO (qtp937738785-17806) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_0.si&checksum=true&compression=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1420282 INFO (qtp937738785-17808) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_0.cfs&checksum=true&compression=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1420283 INFO (qtp937738785-17806) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=segments_3&checksum=true&compression=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1420284 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Total time taken for download (fullCopy=false,bytesDownloaded=2044) : 0 secs (null bytes/sec) to MockDirectoryWrapper(RAMDirectory@53b13d69 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@4fb1e300)
[junit4] 2> 1420285 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=29, maxMergeAtOnceExplicit=28, maxMergedSegmentMB=39.875, floorSegmentMB=0.3759765625, forceMergeDeletesPctAllowed=8.070644201582283, segmentsPerTier=46.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.8625361494032293
[junit4] 2> 1420287 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1420287 INFO (indexFetcher-5682-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@3c712938[collection1] main]
[junit4] 2> 1420290 INFO (searcherExecutor-5678-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@3c712938[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.3.0):c2)))}
[junit4] 2> 1420371 INFO (qtp1882550244-17826) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=*:*&sort=id+desc&wt=javabin&version=2} hits=2 status=0 QTime=0
[junit4] 2> 1420372 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.h.TestReplicationHandler Waited for 100ms and found 2 docs
[junit4] 2> 1420372 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.SolrTestCaseJ4 ###Ending doTestReplicateAfterCoreReload
[junit4] 2> 1420374 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@68823000{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1420374 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1039747988
[junit4] 2> 1420374 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1420374 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@54bc4abe: rootName = null, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@42ca56b9
[junit4] 2> 1420383 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 1420383 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@43faabe7: rootName = null, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@22d2d905
[junit4] 2> 1420387 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 1420387 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@64cdda50: rootName = null, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@56d2b374
[junit4] 2> 1420388 INFO (coreCloseExecutor-5688-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@13efeb11
[junit4] 2> 1420388 INFO (coreCloseExecutor-5688-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1, tag=334490385
[junit4] 2> 1420388 INFO (coreCloseExecutor-5688-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@67a81e70: rootName = null, domain = solr.core.collection1, service url = null, agent id = null] for registry solr.core.collection1 / com.codahale.metrics.MetricRegistry@7f032369
[junit4] 2> 1420403 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@2530af20{/solr,null,UNAVAILABLE}
[junit4] 2> 1420403 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session Stopped scavenging
[junit4] 2> 1420405 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@2db34ab1{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1420405 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=528331551
[junit4] 2> 1420406 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1420406 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@7b642abd: rootName = null, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@2954955f
[junit4] 2> 1420412 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 1420412 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@713ecd29: rootName = null, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@22d2d905
[junit4] 2> 1420417 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 1420417 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@6afd584: rootName = null, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@56d2b374
[junit4] 2> 1420418 INFO (coreCloseExecutor-5690-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@209b4bc3
[junit4] 2> 1420418 INFO (coreCloseExecutor-5690-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1, tag=547048387
[junit4] 2> 1420418 INFO (coreCloseExecutor-5690-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@420bbf36: rootName = null, domain = solr.core.collection1, service url = null, agent id = null] for registry solr.core.collection1 / com.codahale.metrics.MetricRegistry@76b6e383
[junit4] 2> 1420423 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@31c75131{/solr,null,UNAVAILABLE}
[junit4] 2> 1420423 INFO (TEST-TestReplicationHandler.doTestReplicateAfterCoreReload-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session Stopped scavenging
[junit4] 2> 1420428 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.SolrTestCaseJ4 ###Starting doTestStressReplication
[junit4] 2> 1420428 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-003/collection1
[junit4] 2> 1420430 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T21:27:37Z, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
[junit4] 2> 1420431 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1420431 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1420431 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session Scavenging every 600000ms
[junit4] 2> 1420431 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@6cc5d3ee{/solr,null,AVAILABLE}
[junit4] 2> 1420432 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@7d20ccdb{HTTP/1.1,[http/1.1]}{127.0.0.1:44580}
[junit4] 2> 1420432 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.Server Started @1422931ms
[junit4] 2> 1420432 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-003/collection1/data, hostContext=/solr, hostPort=44580}
[junit4] 2> 1420432 ERROR (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1420432 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.3.0
[junit4] 2> 1420432 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 1420432 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1420432 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-02-23T01:43:52.124Z
[junit4] 2> 1420433 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-003/solr.xml
[junit4] 2> 1420436 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored
[junit4] 2> 1420436 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored
[junit4] 2> 1420438 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 1420476 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1420487 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1420487 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1420489 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-003/.
[junit4] 2> 1420489 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1420489 INFO (coreLoadExecutor-5697-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 1420499 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0
[junit4] 2> 1420522 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1420523 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
[junit4] 2> 1420524 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-003/./collection1, trusted=true
[junit4] 2> 1420524 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1' (registry 'solr.core.collection1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@22d0d7e4
[junit4] 2> 1420524 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 1420524 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-003/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-003/./collection1/data/]
[junit4] 2> 1420526 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=28, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 1420563 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1420563 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1420564 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=41, maxMergeAtOnceExplicit=17, maxMergedSegmentMB=1.4189453125, floorSegmentMB=0.6982421875, forceMergeDeletesPctAllowed=12.451018689253155, segmentsPerTier=49.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.15188338868596302
[junit4] 2> 1420565 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@589a0004[collection1] main]
[junit4] 2> 1420565 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-003/collection1/conf
[junit4] 2> 1420565 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Replication enabled for following config files: schema.xml,xslt/dummy.xsl
[junit4] 2> 1420566 INFO (coreLoadExecutor-5697-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 1420567 INFO (searcherExecutor-5698-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@589a0004[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1420568 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.TestReplicationHandler_F3984EEA98A4E19C-001/solr-instance-004/collection1
[junit4] 2> 1420572 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T21:27:37Z, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
[junit4] 2> 1420573 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1420573 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1420573 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.session Scavenging every 600000ms
[junit4] 2> 1420573 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@508dcb6c{/solr,null,AVAILABLE}
[junit4] 2> 1420573 INFO (TEST-TestReplicationHandler.doTestStressReplication-seed#[F3984EEA98A4E19C]) [ ] o.e.j.s.AbstractConnector Start
[...truncated too long message...]
SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@11489082: rootName = solr_58597, domain = solr.core.testSelected3.shard1.replica_n1, service url = null, agent id = null] for registry solr.core.testSelected3.shard1.replica_n1 / com.codahale.metrics.MetricRegistry@720f11ce
[junit4] 2> 2354817 INFO (zkCallback-4774-thread-1-processing-n:127.0.0.1:58597_solr) [n:127.0.0.1:58597_solr c:testSelected3 s:shard1 r:core_node3 x:testSelected3_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.testSelected3.shard1.leader, tag=586938369
[junit4] 2> 2354819 INFO (jetty-closer-4713-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@5ed69e49{/solr,null,UNAVAILABLE}
[junit4] 2> 2354821 INFO (jetty-closer-4713-thread-1) [ ] o.e.j.s.session Stopped scavenging
[junit4] 2> 2354822 ERROR (SUITE-ComputePlanActionTest-seed#[F3984EEA98A4E19C]-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> 2354822 INFO (SUITE-ComputePlanActionTest-seed#[F3984EEA98A4E19C]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:41385 41385
[junit4] 2> 2354924 INFO (Thread-7923) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:41385 41385
[junit4] 2> 2354927 WARN (Thread-7923) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 15 /solr/aliases.json
[junit4] 2> 11 /solr/configs/conf
[junit4] 2> 10 /solr/security.json
[junit4] 2> 10 /solr/collections/testNodeWithMultipleReplicasLost/terms/shard2
[junit4] 2> 10 /solr/collections/testNodeWithMultipleReplicasLost/terms/shard1
[junit4] 2> 7 /solr/collections/testNodeLost/terms/shard1
[junit4] 2> 5 /solr/collections/testSelected1/terms/shard2
[junit4] 2> 5 /solr/collections/testSelected2/terms/shard1
[junit4] 2> 5 /solr/collections/testSelected1/terms/shard1
[junit4] 2> 5 /solr/collections/testSelected2/terms/shard2
[junit4] 2> 5 /solr/collections/testSelected3/terms/shard2
[junit4] 2> 5 /solr/collections/testSelected3/terms/shard1
[junit4] 2> 3 /solr/collections/testNodeAdded/terms/shard1
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 46 /solr/collections/testNodeWithMultipleReplicasLost/state.json
[junit4] 2> 35 /solr/collections/testSelected3/state.json
[junit4] 2> 31 /solr/collections/testSelected1/state.json
[junit4] 2> 27 /solr/collections/testSelected2/state.json
[junit4] 2> 16 /solr/collections/testNodeLost/state.json
[junit4] 2> 15 /solr/clusterprops.json
[junit4] 2> 15 /solr/clusterstate.json
[junit4] 2> 8 /solr/collections/testNodeAdded/state.json
[junit4] 2> 4 /solr/autoscaling.json
[junit4] 2> 3 /solr/overseer_elect/election/73342298293665811-127.0.0.1:58597_solr-n_0000000004
[junit4] 2> 2 /solr/overseer_elect/election/73342298293665800-127.0.0.1:43067_solr-n_0000000001
[junit4] 2> 2 /solr/collections/testNodeWithMultipleReplicasLost/leader_elect/shard1/election/73342298293665800-core_node7-n_0000000000
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 53 /solr/live_nodes
[junit4] 2> 42 /solr/collections
[junit4] 2> 4 /solr/overseer/queue
[junit4] 2> 4 /solr/autoscaling/events/.auto_add_replicas
[junit4] 2> 4 /solr/overseer/collection-queue-work
[junit4] 2> 4 /solr/overseer/queue-work
[junit4] 2> 2 /solr/autoscaling/events/node_lost_trigger
[junit4] 2>
[junit4] 2> NOTE: leaving temporary files on disk at: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.cloud.autoscaling.ComputePlanActionTest_F3984EEA98A4E19C-001
[junit4] 2> Feb 23, 2018 1:59:26 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(Lucene70): {}, docValues:{}, maxPointsInLeafNode=675, maxMBSortInHeap=7.412251179634175, sim=RandomSimilarity(queryNorm=true): {}, locale=en-SG, timezone=Europe/Athens
[junit4] 2> NOTE: Linux 3.13.0-88-generic amd64/Oracle Corporation 1.8.0_144 (64-bit)/cpus=4,threads=1,free=101249272,total=513277952
[junit4] 2> NOTE: All tests run in this JVM: [TestNonDefinedSimilarityFactory, TestJsonFacets, PluginInfoTest, TestLegacyNumericRangeQueryBuilder, VMParamsZkACLAndCredentialsProvidersTest, TestCollationField, TestBlendedInfixSuggestions, ConjunctionSolrSpellCheckerTest, BinaryUpdateRequestHandlerTest, TestZkAclsWithHadoopAuth, MissingSegmentRecoveryTest, BadIndexSchemaTest, TestPayloadCheckQParserPlugin, DistribDocExpirationUpdateProcessorTest, PreAnalyzedFieldManagedSchemaCloudTest, BlobRepositoryCloudTest, SolrCloudReportersTest, TestExceedMaxTermLength, TestSortableTextField, IndexBasedSpellCheckerTest, MetricsHandlerTest, TestConfigSetsAPI, TestDocTermOrds, TestRemoteStreaming, ClassificationUpdateProcessorFactoryTest, TestConfigSetProperties, TestUniqueKeyFieldResource, TestCustomStream, ZkSolrClientTest, TestComponentsName, TestGraphMLResponseWriter, DeleteShardTest, CloudExitableDirectoryReaderTest, TestLuceneMatchVersion, OpenCloseCoreStressTest, TestSolrDeletionPolicy1, TestQuerySenderNoQuery, SolrCoreCheckLockOnStartupTest, TestSortByMinMaxFunction, TestManagedResourceStorage, TestHighlightDedupGrouping, NodeAddedTriggerTest, TemplateUpdateProcessorTest, TestRTimerTree, SolrMetricsIntegrationTest, TestNumericRangeQuery32, TestEmbeddedSolrServerSchemaAPI, TestXmlQParserPlugin, UpdateParamsTest, ActionThrottleTest, TestWordDelimiterFilterFactory, TestWriterPerf, ConfigureRecoveryStrategyTest, TestIBSimilarityFactory, TestExactStatsCache, StatsComponentTest, TestHdfsCloudBackupRestore, DistributedFacetPivotSmallAdvancedTest, TestFieldCacheWithThreads, SolrCoreMetricManagerTest, TestLuceneIndexBackCompat, DebugComponentTest, TestSolrConfigHandlerConcurrent, TestInPlaceUpdatesStandalone, ChaosMonkeyNothingIsSafeTest, TestNodeAddedTrigger, TestDefaultStatsCache, TestConfigReload, SolrPluginUtilsTest, TestSimpleTextCodec, TestCloudJSONFacetJoinDomain, TestCustomDocTransformer, TestStressLucene, TestOmitPositions, TestDistributedMap, TestPrepRecovery, ChangedSchemaMergeTest, DistributedQueryComponentCustomSortTest, NumberUtilsTest, TestStressUserVersions, SimpleFacetsTest, TestCSVResponseWriter, AssignBackwardCompatibilityTest, SegmentsInfoRequestHandlerTest, SuggesterWFSTTest, TestCloudRecovery, DirectUpdateHandlerTest, RequestHandlersTest, LeaderElectionContextKeyTest, ResponseBuilderTest, OutputWriterTest, HdfsAutoAddReplicasIntegrationTest, ChaosMonkeySafeLeaderWithPullReplicasTest, TestStressCloudBlindAtomicUpdates, EchoParamsTest, TestRecoveryHdfs, TestLeaderElectionWithEmptyReplica, AddSchemaFieldsUpdateProcessorFactoryTest, TestPHPSerializedResponseWriter, TestHashPartitioner, JavabinLoaderTest, TestCSVLoader, AnalyticsMergeStrategyTest, SSLMigrationTest, TestGraphTermsQParserPlugin, CreateCollectionCleanupTest, ZkCLITest, TestCustomSort, HighlighterConfigTest, ImplicitSnitchTest, MoveReplicaTest, CursorPagingTest, TestConfig, SubstringBytesRefFilterTest, AssignTest, TestPseudoReturnFields, TestImplicitCoreProperties, UUIDFieldTest, CloneFieldUpdateProcessorFactoryTest, DistributedFacetExistsSmallTest, TestNRTOpen, DistributedTermsComponentTest, TestPhraseSuggestions, TestGroupingSearch, CdcrBidirectionalTest, SpellingQueryConverterTest, TestSubQueryTransformerCrossCore, ExitableDirectoryReaderTest, ChaosMonkeySafeLeaderTest, BasicDistributedZk2Test, UnloadDistributedZkTest, OverseerTest, LeaderElectionIntegrationTest, ShardRoutingTest, RecoveryZkTest, FullSolrCloudDistribCmdsTest, TestReplicationHandler, TestZkChroot, TestDistributedSearch, TestSolr4Spatial, QueryElevationComponentTest, TestSort, TestFiltering, TestLazyCores, TestBadConfig, TestIndexSearcher, SoftAutoCommitTest, TestMergePolicyConfig, TestSolrDeletionPolicy2, MultiTermTest, SampleTest, TestDocSet, TestBinaryField, TestSearchPerf, NumericFieldsTest, MinimalSchemaTest, TestElisionMultitermQuery, ExternalFileFieldSortTest, TestSolrCoreProperties, TestPostingsSolrHighlighter, DirectSolrConnectionTest, SynonymTokenizerTest, TestXIncludeConfig, TestSweetSpotSimilarityFactory, TestDFRSimilarityFactory, TestLMDirichletSimilarityFactory, TestLMJelinekMercerSimilarityFactory, TestBM25SimilarityFactory, TimeZoneUtilsTest, TestFastOutputStream, OpenExchangeRatesOrgProviderTest, PreAnalyzedFieldTest, DateFieldTest, RAMDirectoryFactoryTest, TestSolrJ, TestLRUCache, TestDocumentBuilder, ZkNodePropsTest, SliceStateTest, SystemInfoHandlerTest, CircularListTest, DistributedMLTComponentTest, TestCrossCoreJoin, TestCursorMarkWithoutUniqueKey, TestDistributedMissingSort, TestEmbeddedSolrServerAdminHandler, AddReplicaTest, DeleteInactiveReplicaTest, DistribJoinFromCollectionTest, DistributedVersionInfoTest, HttpPartitionTest, NodeMutatorTest, OutOfBoxZkACLAndCredentialsProvidersTest, OverseerModifyCollectionTest, OverseerRolesTest, OverseerTaskQueueTest, RecoveryAfterSoftCommitTest, TestCloudDeleteByQuery, TestCloudPseudoReturnFields, TestConfigSetsAPIExclusivity, TestConfigSetsAPIZkFailure, TestLeaderInitiatedRecoveryThread, TestOnReconnectListenerSupport, TestRandomFlRTGCloud, TestRequestForwarding, TestShortCircuitedRequests, TestSolrCloudWithDelegationTokens, TestStressInPlaceUpdates, ZkShardTermsTest, CollectionsAPIDistributedZkTest, AutoAddReplicasPlanActionTest, AutoScalingHandlerTest, ComputePlanActionTest]
[junit4] Completed [579/777 (2!)] on J0 in 42.87s, 4 tests, 1 error <<< FAILURES!
[...truncated 50726 lines...]
[JENKINS] Lucene-Solr-Tests-7.x - Build # 440 - Still Unstable
Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-Tests-7.x/440/
2 tests failed.
FAILED: org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration.testNodeMarkersRegistration
Error Message:
Path /autoscaling/nodeAdded/127.0.0.1:10006_solr should have been deleted
Stack Trace:
java.lang.AssertionError: Path /autoscaling/nodeAdded/127.0.0.1:10006_solr should have been deleted
at __randomizedtesting.SeedInfo.seed([16D27FE08C18B5A:19D7AFF206F446B5]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.junit.Assert.assertFalse(Assert.java:68)
at org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration.testNodeMarkersRegistration(TestTriggerIntegration.java:844)
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:1737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984)
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:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
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.handler.admin.AutoscalingHistoryHandlerTest.testHistory
Error Message:
expected:<5> but was:<0>
Stack Trace:
java.lang.AssertionError: expected:<5> but was:<0>
at __randomizedtesting.SeedInfo.seed([16D27FE08C18B5A:6C918303B289745D]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.junit.Assert.assertEquals(Assert.java:456)
at org.apache.solr.handler.admin.AutoscalingHistoryHandlerTest.testHistory(AutoscalingHistoryHandlerTest.java:311)
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:1737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984)
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:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
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 12101 lines...]
[junit4] Suite: org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration
[junit4] 2> 33107 INFO (SUITE-TestTriggerIntegration-seed#[16D27FE08C18B5A]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> Creating dataDir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J1/temp/solr.cloud.autoscaling.sim.TestTriggerIntegration_16D27FE08C18B5A-001/init-core-data-001
[junit4] 2> 33109 WARN (SUITE-TestTriggerIntegration-seed#[16D27FE08C18B5A]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=3 numCloses=3
[junit4] 2> 33109 INFO (SUITE-TestTriggerIntegration-seed#[16D27FE08C18B5A]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true
[junit4] 2> 33112 INFO (SUITE-TestTriggerIntegration-seed#[16D27FE08C18B5A]-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> 33147 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeLostTriggerRestoreState
[junit4] 2> 33149 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 33149 DEBUG (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 33149 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 33150 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 33150 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr]
[junit4] 2> 33150 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion -1
[junit4] 2> 33150 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 33152 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 33152 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 33153 DEBUG (ScheduledTrigger-108-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33159 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 33159 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 33160 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr]
[junit4] 2> 33160 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 33160 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 33160 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 33173 DEBUG (ScheduledTrigger-108-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33194 DEBUG (ScheduledTrigger-108-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33214 DEBUG (ScheduledTrigger-108-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33235 DEBUG (ScheduledTrigger-108-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33257 DEBUG (ScheduledTrigger-108-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 33291 DEBUG (ScheduledTrigger-108-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 33311 DEBUG (simCloudManagerPool-107-thread-1) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 33311 DEBUG (ScheduledTrigger-108-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 33314 DEBUG (simCloudManagerPool-107-thread-1) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 3
[junit4] 2> 33314 DEBUG (simCloudManagerPool-107-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr, 127.0.0.1:10002_solr]
[junit4] 2> 33315 DEBUG (simCloudManagerPool-107-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr, 127.0.0.1:10002_solr]
[junit4] 2> 33323 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 3
[junit4] 2> 33323 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestTriggerIntegration TestTriggerAction init
[junit4] 2> 33323 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 33323 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 3, lastZnodeVersion 3
[junit4] 2> 33323 DEBUG (ScheduledTrigger-108-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_restore_trigger with currently live nodes: 3
[junit4] 2> 33334 DEBUG (ScheduledTrigger-108-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33334 DEBUG (ScheduledTrigger-108-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:10002_solr
[junit4] 2> 33358 DEBUG (ScheduledTrigger-108-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_restore_trigger with currently live nodes: 2
[junit4] 2> 33358 DEBUG (ScheduledTrigger-108-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:10002_solr
[junit4] 2> 33358 DEBUG (ScheduledTrigger-108-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33372 DEBUG (simCloudManagerPool-107-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 33372 DEBUG (simCloudManagerPool-107-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 4
[junit4] 2> 33373 DEBUG (simCloudManagerPool-107-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr]
[junit4] 2> 33373 DEBUG (simCloudManagerPool-107-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr]
[junit4] 2> 33373 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 4
[junit4] 2> 33373 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestTriggerIntegration TestTriggerAction init
[junit4] 2> 33373 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Adding lost node from marker path: 127.0.0.1:10002_solr
[junit4] 2> 33373 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 33373 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 4, lastZnodeVersion 4
[junit4] 2> 33373 DEBUG (ScheduledTrigger-108-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_restore_trigger with currently live nodes: 2
[junit4] 2> 33373 DEBUG (ScheduledTrigger-108-thread-4) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:10002_solr]
[junit4] 2> 33374 DEBUG (ScheduledTrigger-108-thread-4) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"45b8807ab4571bTbkbktozd6313q2f8styh71o5v",
[junit4] 2> "source":"node_lost_restore_trigger",
[junit4] 2> "eventTime":19624635346999067,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624635346999067],
[junit4] 2> "nodeNames":["127.0.0.1:10002_solr"]}}
[junit4] 2> 33374 DEBUG (ScheduledTrigger-108-thread-4) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, node_lost_restore_trigger]
[junit4] 2> 33417 DEBUG (AutoscalingActionExecutor-109-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"45b8807ab4571bTbkbktozd6313q2f8styh71o5v",
[junit4] 2> "source":"node_lost_restore_trigger",
[junit4] 2> "eventTime":19624635346999067,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624635346999067],
[junit4] 2> "_enqueue_time_":19624635424156017,
[junit4] 2> "nodeNames":["127.0.0.1:10002_solr"]}}
[junit4] 2> 33419 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNodeLostTriggerRestoreState
[junit4] 2> 33419 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase
[junit4] 2>
[junit4] 2> 33419 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2> 33419 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ############ FINAL CLUSTER STATS ############
[junit4] 2> 33419 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2>
[junit4] 2> 33419 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Live nodes: 2
[junit4] 2> 33419 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Empty nodes: 2
[junit4] 2> 33419 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Dead nodes: 1
[junit4] 2> 33420 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## 127.0.0.1:10002_solr
[junit4] 2> 33420 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Collections: []
[junit4] 2> 33420 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Max replicas per node: 0
[junit4] 2> 33420 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Min replicas per node: 0
[junit4] 2> 33420 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Total replicas: 0
[junit4] 2> 33420 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Final Solr op counts ##########
[junit4] 2> 33421 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - autoscaling 2
[junit4] 2> 33421 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - update 1
[junit4] 2> 33421 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Autoscaling event counts ###########
[junit4] 2> 33422 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## * Trigger: node_lost_restore_trigger
[junit4] 2> 33422 INFO (TEST-TestTriggerIntegration.testNodeLostTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - STARTED 1
[junit4] 2> 33426 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeAddedTriggerRestoreState
[junit4] 2> 33426 DEBUG (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 5
[junit4] 2> 33426 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 5
[junit4] 2> 33427 DEBUG (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimNodeStateProvider - removing dead node values: 127.0.0.1:10002_solr
[junit4] 2> 33429 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 33429 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 33429 DEBUG (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 33429 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 33430 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Interrupted
[junit4] 2> java.lang.InterruptedException
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
[junit4] 2> at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
[junit4] 2> at org.apache.solr.cloud.autoscaling.OverseerTriggerThread.run(OverseerTriggerThread.java:163)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 33471 WARN (AutoscalingActionExecutor-109-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Exception executing actions
[junit4] 2> org.apache.lucene.store.AlreadyClosedException: ScheduledTrigger node_lost_restore_trigger has been closed.
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers$ScheduledTrigger.dequeue(ScheduledTriggers.java:523)
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers.lambda$null$3(ScheduledTriggers.java:308)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188)
[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> 33472 DEBUG (AutoscalingActionExecutor-109-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 2776 ms for event id=45b8807ab4571bTbkbktozd6313q2f8styh71o5v
[junit4] 2> 33474 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 33474 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 6
[junit4] 2> 33474 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr]
[junit4] 2> 33474 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 6, lastZnodeVersion -1
[junit4] 2> 33474 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 6
[junit4] 2> 33483 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 33483 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 6, lastZnodeVersion 6
[junit4] 2> 33484 DEBUG (ScheduledTrigger-111-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33504 DEBUG (ScheduledTrigger-111-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33558 DEBUG (ScheduledTrigger-111-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33578 DEBUG (ScheduledTrigger-111-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33584 DEBUG (simCloudManagerPool-110-thread-1) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 33584 DEBUG (simCloudManagerPool-110-thread-1) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 7
[junit4] 2> 33597 DEBUG (simCloudManagerPool-110-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr]
[junit4] 2> 33597 DEBUG (simCloudManagerPool-110-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_restore_trigger instantiated with properties: {event=nodeAdded, waitFor=5, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$TestTriggerAction}], enabled=true}
[junit4] 2> 33597 DEBUG (simCloudManagerPool-110-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr]
[junit4] 2> 33597 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 7
[junit4] 2> 33597 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestTriggerIntegration TestTriggerAction init
[junit4] 2> 33598 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 7, lastZnodeVersion 7
[junit4] 2> 33598 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_restore_trigger
[junit4] 2> 33598 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 33599 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33619 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_restore_trigger
[junit4] 2> 33619 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 33619 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:10003_solr at time 19624647651779567
[junit4] 2> 33619 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 33640 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_restore_trigger
[junit4] 2> 33640 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 33640 DEBUG (ScheduledTrigger-111-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 33750 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_restore_trigger
[junit4] 2> 33751 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 33751 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_restore_trigger firing registered processor for nodes: [127.0.0.1:10003_solr] added at times [19624647651779567], now=19624654221327667
[junit4] 2> 33751 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"45b883582063efTbkbktozd6313q2f8styh71o5x",
[junit4] 2> "source":"node_added_restore_trigger",
[junit4] 2> "eventTime":19624647651779567,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624647651779567],
[junit4] 2> "nodeNames":["127.0.0.1:10003_solr"]}}
[junit4] 2> 33751 DEBUG (ScheduledTrigger-111-thread-4) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, node_added_restore_trigger]
[junit4] 2> 33753 DEBUG (simCloudManagerPool-110-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 33753 DEBUG (simCloudManagerPool-110-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 8
[junit4] 2> 33753 DEBUG (simCloudManagerPool-110-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr, 127.0.0.1:10003_solr]
[junit4] 2> 33753 DEBUG (simCloudManagerPool-110-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_restore_trigger instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$TestTriggerAction}], enabled=true}
[junit4] 2> 33753 DEBUG (simCloudManagerPool-110-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr, 127.0.0.1:10003_solr]
[junit4] 2> 33753 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 8
[junit4] 2> 33772 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestTriggerIntegration TestTriggerAction init
[junit4] 2> 33772 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 8, lastZnodeVersion 8
[junit4] 2> 33777 DEBUG (AutoscalingActionExecutor-112-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"45b883582063efTbkbktozd6313q2f8styh71o5x",
[junit4] 2> "source":"node_added_restore_trigger",
[junit4] 2> "eventTime":19624647651779567,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624647651779567],
[junit4] 2> "_enqueue_time_":19624654266748467,
[junit4] 2> "nodeNames":["127.0.0.1:10003_solr"]}}
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNodeAddedTriggerRestoreState
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase
[junit4] 2>
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ############ FINAL CLUSTER STATS ############
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2>
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Live nodes: 3
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Empty nodes: 3
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Dead nodes: 0
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Collections: []
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Max replicas per node: 0
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Min replicas per node: 0
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Total replicas: 0
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Final Solr op counts ##########
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - autoscaling 2
[junit4] 2> 33778 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - update 1
[junit4] 2> 33779 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Autoscaling event counts ###########
[junit4] 2> 33779 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## * Trigger: node_added_restore_trigger
[junit4] 2> 33779 INFO (TEST-TestTriggerIntegration.testNodeAddedTriggerRestoreState-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - STARTED 1
[junit4] 2> 33800 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeAddedTrigger
[junit4] 2> 33800 DEBUG (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 9
[junit4] 2> 33802 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 9
[junit4] 2> 33802 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 33802 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 33802 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 9, lastZnodeVersion 9
[junit4] 2> 33803 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 33803 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 33803 DEBUG (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 33804 WARN (AutoscalingActionExecutor-112-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Exception executing actions
[junit4] 2> org.apache.lucene.store.AlreadyClosedException: ScheduledTrigger node_added_restore_trigger has been closed.
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers$ScheduledTrigger.dequeue(ScheduledTriggers.java:523)
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers.lambda$null$3(ScheduledTriggers.java:308)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188)
[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> 33804 DEBUG (AutoscalingActionExecutor-112-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 1383 ms for event id=45b883582063efTbkbktozd6313q2f8styh71o5x
[junit4] 2> 33815 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 33815 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 10
[junit4] 2> 33815 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr]
[junit4] 2> 33816 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 10, lastZnodeVersion -1
[junit4] 2> 33816 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 10
[junit4] 2> 33829 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 33829 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 10, lastZnodeVersion 10
[junit4] 2> 33832 DEBUG (ScheduledTrigger-114-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33852 DEBUG (ScheduledTrigger-114-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33873 DEBUG (ScheduledTrigger-114-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33893 DEBUG (ScheduledTrigger-114-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33913 DEBUG (ScheduledTrigger-114-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 33925 DEBUG (simCloudManagerPool-113-thread-1) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 33926 DEBUG (simCloudManagerPool-113-thread-1) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 11
[junit4] 2> 33926 DEBUG (simCloudManagerPool-113-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr]
[junit4] 2> 33926 DEBUG (simCloudManagerPool-113-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr]
[junit4] 2> 33926 DEBUG (simCloudManagerPool-113-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$TestTriggerAction}], enabled=true}
[junit4] 2> 33926 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 11
[junit4] 2> 33927 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestTriggerIntegration TestTriggerAction init
[junit4] 2> 33927 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 11, lastZnodeVersion 11
[junit4] 2> 33927 DEBUG (ScheduledTrigger-114-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 33927 DEBUG (ScheduledTrigger-114-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 33935 DEBUG (ScheduledTrigger-114-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 33947 DEBUG (ScheduledTrigger-114-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 33947 DEBUG (ScheduledTrigger-114-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 33947 DEBUG (ScheduledTrigger-114-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:10004_solr at time 19624664053516417
[junit4] 2> 33955 DEBUG (ScheduledTrigger-114-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 33968 DEBUG (ScheduledTrigger-114-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 33968 DEBUG (ScheduledTrigger-114-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 33968 DEBUG (ScheduledTrigger-114-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger firing registered processor for nodes: [127.0.0.1:10004_solr] added at times [19624664053516417], now=19624665072050967
[junit4] 2> 33968 DEBUG (ScheduledTrigger-114-thread-2) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"45b88729bf0881Tbkbktozd6313q2f8styh71o5z",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":19624664053516417,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624664053516417],
[junit4] 2> "nodeNames":["127.0.0.1:10004_solr"]}}
[junit4] 2> 33971 DEBUG (ScheduledTrigger-114-thread-2) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, node_added_trigger]
[junit4] 2> 34017 DEBUG (AutoscalingActionExecutor-115-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"45b88729bf0881Tbkbktozd6313q2f8styh71o5z",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":19624664053516417,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624664053516417],
[junit4] 2> "_enqueue_time_":19624665249936917,
[junit4] 2> "nodeNames":["127.0.0.1:10004_solr"]}}
[junit4] 2> 34051 DEBUG (AutoscalingActionExecutor-115-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .auto_add_replicas after 100ms
[junit4] 2> 34051 DEBUG (AutoscalingActionExecutor-115-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_added_trigger after 100ms
[junit4] 2> 34051 DEBUG (AutoscalingActionExecutor-115-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 1696 ms for event id=45b88729bf0881Tbkbktozd6313q2f8styh71o5z
[junit4] 2> 34055 DEBUG (simCloudManagerPool-113-thread-4) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 34056 DEBUG (simCloudManagerPool-113-thread-4) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 12
[junit4] 2> 34056 DEBUG (simCloudManagerPool-113-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10004_solr, 127.0.0.1:10000_solr]
[junit4] 2> 34056 DEBUG (simCloudManagerPool-113-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10004_solr, 127.0.0.1:10000_solr]
[junit4] 2> 34056 DEBUG (simCloudManagerPool-113-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$TestTriggerAction}], enabled=true}
[junit4] 2> 34056 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 12
[junit4] 2> 34057 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 12, lastZnodeVersion 12
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNodeAddedTrigger
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase
[junit4] 2>
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ############ FINAL CLUSTER STATS ############
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2>
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Live nodes: 3
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Empty nodes: 3
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Dead nodes: 0
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Collections: []
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Max replicas per node: 0
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Min replicas per node: 0
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Total replicas: 0
[junit4] 2> 34097 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Final Solr op counts ##########
[junit4] 2> 34098 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - autoscaling 2
[junit4] 2> 34098 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - update 2
[junit4] 2> 34098 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Autoscaling event counts ###########
[junit4] 2> 34098 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## * Trigger: node_added_trigger
[junit4] 2> 34098 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - STARTED 1
[junit4] 2> 34098 INFO (TEST-TestTriggerIntegration.testNodeAddedTrigger-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - SUCCEEDED 1
[junit4] 2> 34124 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeMarkersRegistration
[junit4] 2> 34124 DEBUG (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 13
[junit4] 2> 34125 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 34125 DEBUG (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 34125 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 34132 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 34132 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 14
[junit4] 2> 34132 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10004_solr]
[junit4] 2> 34132 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 14, lastZnodeVersion -1
[junit4] 2> 34132 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 14
[junit4] 2> 34139 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 34139 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 14, lastZnodeVersion 14
[junit4] 2> 34139 DEBUG (ScheduledTrigger-117-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34159 DEBUG (ScheduledTrigger-117-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34184 DEBUG (ScheduledTrigger-117-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34207 DEBUG (ScheduledTrigger-117-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34227 DEBUG (ScheduledTrigger-117-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34233 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.TestTriggerIntegration ====== KILL OVERSEER 1
[junit4] 2> 34233 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 34233 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 34236 DEBUG (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 34239 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 14
[junit4] 2> 34240 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34240 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 14, lastZnodeVersion -1
[junit4] 2> 34241 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 14
[junit4] 2> 34242 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Adding lost node from marker path: 127.0.0.1:10004_solr
[junit4] 2> 34243 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 34243 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 14, lastZnodeVersion 14
[junit4] 2> 34243 DEBUG (ScheduledTrigger-120-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34244 DEBUG (ScheduledTrigger-120-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:10004_solr
[junit4] 2> 34264 DEBUG (ScheduledTrigger-120-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34285 DEBUG (ScheduledTrigger-120-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34305 DEBUG (ScheduledTrigger-120-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34325 DEBUG (ScheduledTrigger-120-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34337 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.TestTriggerIntegration ====== ADD TRIGGERS
[junit4] 2> 34344 DEBUG (simCloudManagerPool-119-thread-1) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 34347 DEBUG (ScheduledTrigger-120-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34348 DEBUG (simCloudManagerPool-119-thread-1) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 15
[junit4] 2> 34354 DEBUG (simCloudManagerPool-119-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34354 DEBUG (simCloudManagerPool-119-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34354 DEBUG (simCloudManagerPool-119-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$TestEventMarkerAction}], enabled=true}
[junit4] 2> 34354 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 15
[junit4] 2> 34355 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestTriggerIntegration TestEventMarkerAction init
[junit4] 2> 34355 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 15, lastZnodeVersion 15
[junit4] 2> 34355 DEBUG (ScheduledTrigger-120-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 34355 DEBUG (ScheduledTrigger-120-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 34356 DEBUG (simCloudManagerPool-119-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 34356 DEBUG (simCloudManagerPool-119-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 16
[junit4] 2> 34356 DEBUG (simCloudManagerPool-119-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34356 DEBUG (simCloudManagerPool-119-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34356 DEBUG (simCloudManagerPool-119-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34356 DEBUG (simCloudManagerPool-119-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$TestEventMarkerAction}], enabled=true}
[junit4] 2> 34356 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 16
[junit4] 2> 34357 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestTriggerIntegration TestEventMarkerAction init
[junit4] 2> 34357 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 16, lastZnodeVersion 16
[junit4] 2> 34357 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.TestTriggerIntegration ====== ADD NODE 1
[junit4] 2> 34363 DEBUG (ScheduledTrigger-120-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 3
[junit4] 2> 34367 DEBUG (ScheduledTrigger-120-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 34376 DEBUG (ScheduledTrigger-120-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 34376 DEBUG (ScheduledTrigger-120-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 34376 DEBUG (ScheduledTrigger-120-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:10006_solr at time 19624685471740917
[junit4] 2> 34384 DEBUG (ScheduledTrigger-120-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 3
[junit4] 2> 34387 DEBUG (ScheduledTrigger-120-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 34459 DEBUG (ScheduledTrigger-120-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 34459 DEBUG (ScheduledTrigger-120-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 34459 DEBUG (ScheduledTrigger-120-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger firing registered processor for nodes: [127.0.0.1:10006_solr] added at times [19624685471740917], now=19624689640036217
[junit4] 2> 34459 DEBUG (ScheduledTrigger-120-thread-4) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"45b88c265f33f5Tbkbktozd6313q2f8styh71o62",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":19624685471740917,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624685471740917],
[junit4] 2> "nodeNames":["127.0.0.1:10006_solr"]}}
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNodeMarkersRegistration
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase
[junit4] 2>
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ############ FINAL CLUSTER STATS ############
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2>
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Live nodes: 3
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Empty nodes: 3
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Dead nodes: 1
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## 127.0.0.1:10004_solr
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Collections: []
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Max replicas per node: 0
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Min replicas per node: 0
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Total replicas: 0
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Final Solr op counts ##########
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - autoscaling 2
[junit4] 2> 34460 INFO (TEST-TestTriggerIntegration.testNodeMarkersRegistration-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Autoscaling event counts ###########
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestTriggerIntegration -Dtests.method=testNodeMarkersRegistration -Dtests.seed=16D27FE08C18B5A -Dtests.multiplier=2 -Dtests.slow=true -Dtests.locale=sv-SE -Dtests.timezone=Europe/Nicosia -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[junit4] 2> 34463 DEBUG (ScheduledTrigger-120-thread-4) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, node_lost_trigger, node_added_trigger]
[junit4] FAILURE 0.37s J1 | TestTriggerIntegration.testNodeMarkersRegistration <<<
[junit4] > Throwable #1: java.lang.AssertionError: Path /autoscaling/nodeAdded/127.0.0.1:10006_solr should have been deleted
[junit4] > at __randomizedtesting.SeedInfo.seed([16D27FE08C18B5A:19D7AFF206F446B5]:0)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration.testNodeMarkersRegistration(TestTriggerIntegration.java:844)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 34485 INFO (TEST-TestTriggerIntegration.testTriggerThrottling-seed#[16D27FE08C18B5A]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testTriggerThrottling
[junit4] 2> 34486 DEBUG (TEST-TestTriggerIntegration.testTriggerThrottling-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 17
[junit4] 2> 34486 DEBUG (TEST-TestTriggerIntegration.testTriggerThrottling-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimNodeStateProvider - removing dead node values: 127.0.0.1:10004_solr
[junit4] 2> 34486 INFO (TEST-TestTriggerIntegration.testTriggerThrottling-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 34486 DEBUG (TEST-TestTriggerIntegration.testTriggerThrottling-seed#[16D27FE08C18B5A]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 34486 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 34487 DEBUG (AutoscalingActionExecutor-121-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"45b88c265f33f5Tbkbktozd6313q2f8styh71o62",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":19624685471740917,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624685471740917],
[junit4] 2> "_enqueue_time_":19624689866932717,
[junit4] 2> "nodeNames":["127.0.0.1:10006_solr"]}}
[junit4] 2> 34487 WARN (AutoscalingActionExecutor-121-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Exception executing actions
[junit4] 2> org.apache.lucene.store.AlreadyClosedException: ScheduledTrigger node_added_trigger has been closed.
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers$ScheduledTrigger.dequeue(ScheduledTriggers.java:523)
[junit4] 2> at org.apache.solr.cloud.autoscaling.ScheduledTriggers.lambda$null$3(ScheduledTriggers.java:308)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188)
[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> 34487 DEBUG (AutoscalingActionExecutor-121-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 127 ms for event id=45b88c265f33f5Tbkbktozd6313q2f8styh71o62
[junit4] 2> 34488 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 34488 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 18
[junit4] 2> 34488 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34488 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 18, lastZnodeVersion -1
[junit4] 2> 34488 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 18
[junit4] 2> 34488 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 34489 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 18, lastZnodeVersion 18
[junit4] 2> 34489 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34509 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34530 DEBUG (ScheduledTrigger-123-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34550 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34570 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34651 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34666 DEBUG (simCloudManagerPool-122-thread-1) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 34666 DEBUG (simCloudManagerPool-122-thread-1) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 19
[junit4] 2> 34666 DEBUG (simCloudManagerPool-122-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34666 DEBUG (simCloudManagerPool-122-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34667 DEBUG (simCloudManagerPool-122-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 34672 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 19
[junit4] 2> 34672 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestTriggerIntegration TestTriggerAction init
[junit4] 2> 34672 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 19, lastZnodeVersion 19
[junit4] 2> 34675 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34675 DEBUG (ScheduledTrigger-123-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 34675 DEBUG (ScheduledTrigger-123-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 34681 DEBUG (simCloudManagerPool-122-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 34681 DEBUG (simCloudManagerPool-122-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 20
[junit4] 2> 34681 DEBUG (simCloudManagerPool-122-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34681 DEBUG (simCloudManagerPool-122-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 34681 DEBUG (simCloudManagerPool-122-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34682 DEBUG (simCloudManagerPool-122-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr]
[junit4] 2> 34682 DEBUG (simCloudManagerPool-122-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 34682 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 20
[junit4] 2> 34682 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestTriggerIntegration TestTriggerAction init
[junit4] 2> 34682 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 20, lastZnodeVersion 20
[junit4] 2> 34682 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 34682 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 34682 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:10007_solr at time 19624700811712367
[junit4] 2> 34682 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 firing registered processor for nodes: [127.0.0.1:10007_solr] added at times [19624700811712367], now=19624700813530517
[junit4] 2> 34683 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"45b88fb8b4976fTbkbktozd6313q2f8styh71o64",
[junit4] 2> "source":"node_added_trigger2",
[junit4] 2> "eventTime":19624700811712367,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624700811712367],
[junit4] 2> "nodeNames":["127.0.0.1:10007_solr"]}}
[junit4] 2> 34691 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, node_added_trigger2, node_added_trigger1]
[junit4] 2> 34692 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"45b88fb8b4976fTbkbktozd6313q2f8styh71o64",
[junit4] 2> "source":"node_added_trigger2",
[junit4] 2> "eventTime":19624700811712367,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624700811712367],
[junit4] 2> "_enqueue_time_":19624701234765617,
[junit4] 2> "nodeNames":["127.0.0.1:10007_solr"]}}
[junit4] 2> 34692 INFO (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.s.TestTriggerIntegration action executed from node_added_trigger2
[junit4] 2> 34716 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .auto_add_replicas after 100ms
[junit4] 2> 34716 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_added_trigger2 after 100ms
[junit4] 2> 34716 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_added_trigger1 after 100ms
[junit4] 2> 34717 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 1248 ms for event id=45b88fb8b4976fTbkbktozd6313q2f8styh71o64
[junit4] 2> 34816 DEBUG (ScheduledTrigger-123-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 34817 DEBUG (ScheduledTrigger-123-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 34817 DEBUG (ScheduledTrigger-123-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 34817 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 34817 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 3
[junit4] 2> 34817 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:10007_solr at time 19624707535326967
[junit4] 2> 34817 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 firing registered processor for nodes: [127.0.0.1:10007_solr] added at times [19624707535326967], now=19624707536920017
[junit4] 2> 34817 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"45b8914976cef7Tbkbktozd6313q2f8styh71o67",
[junit4] 2> "source":"node_added_trigger1",
[junit4] 2> "eventTime":19624707535326967,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624707535326967],
[junit4] 2> "nodeNames":["127.0.0.1:10007_solr"]}}
[junit4] 2> 34817 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [.auto_add_replicas, node_added_trigger2, node_added_trigger1]
[junit4] 2> 34818 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"45b8914976cef7Tbkbktozd6313q2f8styh71o67",
[junit4] 2> "source":"node_added_trigger1",
[junit4] 2> "eventTime":19624707535326967,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624707535326967],
[junit4] 2> "_enqueue_time_":19624707548402767,
[junit4] 2> "nodeNames":["127.0.0.1:10007_solr"]}}
[junit4] 2> 34818 INFO (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.s.TestTriggerIntegration last action at 19624701287950667 time = 19624707588424367
[junit4] 2> 34818 INFO (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.s.TestTriggerIntegration action executed from node_added_trigger1
[junit4] 2> 34819 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .auto_add_replicas after 100ms
[junit4] 2> 34819 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_added_trigger2 after 100ms
[junit4] 2> 34819 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_added_trigger1 after 100ms
[junit4] 2> 34819 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 41 ms for event id=45b8914976cef7Tbkbktozd6313q2f8styh71o67
[junit4] 2> 34830 DEBUG (simCloudManagerPool-122-thread-7) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 34830 DEBUG (simCloudManagerPool-122-thread-7) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 21
[junit4] 2> 34830 DEBUG (simCloudManagerPool-122-thread-7) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr, 127.0.0.1:10007_solr]
[junit4] 2> 34830 DEBUG (simCloudManagerPool-122-thread-7) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 34830 DEBUG (simCloudManagerPool-122-thread-7) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr, 127.0.0.1:10007_solr]
[junit4] 2> 34830 DEBUG (simCloudManagerPool-122-thread-7) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr, 127.0.0.1:10007_solr]
[junit4] 2> 34830 DEBUG (simCloudManagerPool-122-thread-7) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 34830 DEBUG (simCloudManagerPool-122-thread-7) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr, 127.0.0.1:10007_solr]
[junit4] 2> 34831 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 21
[junit4] 2> 34831 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestTriggerIntegration TestTriggerAction init
[junit4] 2> 34831 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 21, lastZnodeVersion 21
[junit4] 2> 34831 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger1 with currently live nodes: 3
[junit4] 2> 34836 DEBUG (simCloudManagerPool-122-thread-8) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 34836 DEBUG (simCloudManagerPool-122-thread-8) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 22
[junit4] 2> 34836 DEBUG (simCloudManagerPool-122-thread-8) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr, 127.0.0.1:10007_solr]
[junit4] 2> 34836 DEBUG (simCloudManagerPool-122-thread-8) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger2 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 34836 DEBUG (simCloudManagerPool-122-thread-8) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr, 127.0.0.1:10007_solr]
[junit4] 2> 34836 DEBUG (simCloudManagerPool-122-thread-8) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr, 127.0.0.1:10007_solr]
[junit4] 2> 34836 DEBUG (simCloudManagerPool-122-thread-8) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger1 instantiated with properties: {event=nodeAdded, waitFor=0, actions=[{name=test, class=org.apache.solr.cloud.autoscaling.sim.TestTriggerIntegration$ThrottlingTesterAction}], enabled=true}
[junit4] 2> 34836 DEBUG (simCloudManagerPool-122-thread-8) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr, 127.0.0.1:10007_solr]
[junit4] 2> 34836 DEBUG (simCloudManagerPool-122-thread-8) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10006_solr, 127.0.0.1:10005_solr, 127.0.0.1:10007_solr]
[junit4] 2> 34836 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 22
[junit4] 2> 34837 INFO (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.s.TestTriggerIntegration TestTriggerAction init
[junit4] 2> 34837 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 22, lastZnodeVersion 22
[junit4] 2> 34837 DEBUG (ScheduledTrigger-123-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger2 with currently live nodes: 3
[junit4] 2> 34851 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger1 with currently live nodes: 2
[junit4] 2> 34851 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:10007_solr
[junit4] 2> 34851 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:10007_solr]
[junit4] 2> 34851 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"45b891b00fa341Tbkbktozd6313q2f8styh71o6a",
[junit4] 2> "source":"node_lost_trigger1",
[junit4] 2> "eventTime":19624709256618817,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624709256618817],
[junit4] 2> "nodeNames":["127.0.0.1:10007_solr"]}}
[junit4] 2> 34852 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Pausing all triggers: [node_lost_trigger2, .auto_add_replicas, node_added_trigger2, node_lost_trigger1, node_added_trigger1]
[junit4] 2> 34856 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"45b891b00fa341Tbkbktozd6313q2f8styh71o6a",
[junit4] 2> "source":"node_lost_trigger1",
[junit4] 2> "eventTime":19624709256618817,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[19624709256618817],
[junit4] 2> "_enqueue_time_":19624709269112017,
[junit4] 2> "nodeNames":["127.0.0.1:10007_solr"]}}
[junit4] 2> 34856 INFO (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.s.TestTriggerIntegration action executed from node_lost_trigger1
[junit4] 2> 34857 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_lost_trigger2 after 100ms
[junit4] 2> 34857 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: .auto_add_replicas after 100ms
[junit4] 2> 34857 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_added_trigger2 after 100ms
[junit4] 2> 34857 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_lost_trigger1 after 100ms
[junit4] 2> 34857 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers Resuming trigger: node_added_trigger1 after 100ms
[junit4] 2> 34857 DEBUG (AutoscalingActionExecutor-124-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 53 ms for event id=45b891b00fa341Tbkbktozd6313q2f8styh71o6a
[junit4] 2> 34957 DEBUG (ScheduledTrigger-123-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 34957 DEBUG (ScheduledTrigger-123-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:10007_solr
[junit4] 2> 34957 DEBUG (ScheduledTrigger-123-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger1
[junit4] 2> 34957 DEBUG (ScheduledTrigger-123-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 34957 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger2
[junit4] 2> 34958 DEBUG (ScheduledTrigger-123-thread-1) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 34958 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger2 with currently live nodes: 2
[junit4] 2> 34958 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:10007_solr
[junit4] 2> 34958 DEBUG (ScheduledTrigger-123-thread-4) [ ] o.a.s.c.a.NodeLostTrigger NodeLostT
[...truncated too long message...]
junit4] 2> 2329774 INFO (coreCloseExecutor-10227-thread-3) [n:127.0.0.1:42126_solr c:AutoscalingHistoryHandlerTest_collection s:shard1 r:core_node5 x:AutoscalingHistoryHandlerTest_collection_shard1_replica_n2] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.AutoscalingHistoryHandlerTest_collection.shard1.leader, tag=1536081803
[junit4] 2> 2329775 INFO (jetty-closer-6514-thread-2) [ ] o.a.s.c.Overseer Overseer (id=73343862572515333-127.0.0.1:42126_solr-n_0000000000) closing
[junit4] 2> 2329776 INFO (OverseerStateUpdate-73343862572515333-127.0.0.1:42126_solr-n_0000000000) [n:127.0.0.1:42126_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:42126_solr
[junit4] 2> 2329776 WARN (OverseerAutoScalingTriggerThread-73343862572515333-127.0.0.1:42126_solr-n_0000000000) [n:127.0.0.1:42126_solr ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 2329776 DEBUG (jetty-closer-6514-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 2329777 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn Unable to read additional data from client sessionid 0x10491dabb170005, likely client has closed socket
[junit4] 2> 2329781 INFO (jetty-closer-6514-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@1b706e9a{/solr,null,UNAVAILABLE}
[junit4] 2> 2329781 INFO (jetty-closer-6514-thread-2) [ ] o.e.j.s.session Stopped scavenging
[junit4] 2> 2329781 ERROR (SUITE-AutoscalingHistoryHandlerTest-seed#[16D27FE08C18B5A]-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> 2329781 INFO (SUITE-AutoscalingHistoryHandlerTest-seed#[16D27FE08C18B5A]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:60101 60101
[junit4] 2> 2329953 INFO (Thread-10982) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:60101 60101
[junit4] 2> 2329953 WARN (Thread-10982) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 11 /solr/aliases.json
[junit4] 2> 4 /solr/collections/AutoscalingHistoryHandlerTest_collection/terms/shard1
[junit4] 2> 3 /solr/security.json
[junit4] 2> 3 /solr/configs/AutoscalingHistoryHandlerTest_collection.AUTOCREATED/managed-schema
[junit4] 2> 2 /solr/collections/.system/terms/shard1
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 11 /solr/clusterstate.json
[junit4] 2> 11 /solr/clusterprops.json
[junit4] 2> 7 /solr/collections/AutoscalingHistoryHandlerTest_collection/state.json
[junit4] 2> 7 /solr/collections/.system/state.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 11 /solr/live_nodes
[junit4] 2> 11 /solr/collections
[junit4] 2>
[junit4] 2> NOTE: leaving temporary files on disk at: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.x/solr/build/solr-core/test/J0/temp/solr.handler.admin.AutoscalingHistoryHandlerTest_16D27FE08C18B5A-001
[junit4] 2> Feb 23, 2018 8:36:51 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(Lucene70): {action_s=FSTOrd50, event.source_s=PostingsFormat(name=LuceneVarGapDocFreqInterval), type=FSTOrd50, before.actions_ss=PostingsFormat(name=LuceneVarGapDocFreqInterval), event.property._enqueue_time__ss=FSTOrd50, after.actions_ss=PostingsFormat(name=MockRandom), stage_s=FSTOrd50, event.id_s=PostingsFormat(name=LuceneFixedGap), event.property.eventTimes_ss=FSTOrd50, source_s=PostingsFormat(name=LuceneFixedGap), event.type_s=FSTOrd50, id=PostingsFormat(name=LuceneFixedGap), event.property.nodeNames_ss=FSTOrd50}, docValues:{_version_=DocValuesFormat(name=Asserting), event.time_l=DocValuesFormat(name=Asserting), timestamp=DocValuesFormat(name=Asserting)}, maxPointsInLeafNode=457, maxMBSortInHeap=7.573683662405026, sim=RandomSimilarity(queryNorm=true): {}, locale=is-IS, timezone=Pacific/Majuro
[junit4] 2> NOTE: Linux 3.13.0-88-generic amd64/Oracle Corporation 1.8.0_144 (64-bit)/cpus=4,threads=1,free=254164976,total=523763712
[junit4] 2> NOTE: All tests run in this JVM: [TestCryptoKeys, ClassificationUpdateProcessorFactoryTest, TestSchemaSimilarityResource, TestLuceneIndexBackCompat, CollectionsAPIAsyncDistributedZkTest, DirectUpdateHandlerTest, DebugComponentTest, TestHttpShardHandlerFactory, SuggesterWFSTTest, FieldAnalysisRequestHandlerTest, ExitableDirectoryReaderTest, OpenCloseCoreStressTest, TestSolrCoreParser, JSONWriterTest, ResponseBuilderTest, TestSolrCloudWithDelegationTokens, TestSortableTextField, UtilsToolTest, TolerantUpdateProcessorTest, TestFieldCollectionResource, SystemLogListenerTest, TermVectorComponentDistributedTest, TestCollapseQParserPlugin, TestLeaderElectionWithEmptyReplica, TestDocumentBuilder, OutputWriterTest, ImplicitSnitchTest, TestSimDistributedQueue, HdfsSyncSliceTest, BadIndexSchemaTest, TestMultiWordSynonyms, ShardRoutingTest, TestUniqueKeyFieldResource, TestSortByMinMaxFunction, TestShortCircuitedRequests, SolrIndexSplitterTest, SolrRequestParserTest, TestOmitPositions, AnalysisErrorHandlingTest, DistributedTermsComponentTest, ChaosMonkeySafeLeaderWithPullReplicasTest, TestCustomDocTransformer, DistribDocExpirationUpdateProcessorTest, TestHighFrequencyDictionaryFactory, TestSlowCompositeReaderWrapper, CheckHdfsIndexTest, TestCSVResponseWriter, V2StandaloneTest, FacetPivotSmallTest, TestConfigSetProperties, SolrIndexConfigTest, SolrCloudReportersTest, TestCloudSchemaless, TestNodeAddedTrigger, ZkNodePropsTest, JavabinLoaderTest, TestTlogReplica, TestComponentsName, TestFieldCacheWithThreads, SolrMetricsIntegrationTest, TestRTimerTree, AutoScalingHandlerTest, SolrCoreCheckLockOnStartupTest, FullHLLTest, TestRecoveryHdfs, SpellingQueryConverterTest, CloudExitableDirectoryReaderTest, BinaryUpdateRequestHandlerTest, DefaultValueUpdateProcessorTest, TestWordDelimiterFilterFactory, TestSolrCloudSnapshots, TestFieldTypeResource, TestFieldCacheSort, TestManagedSchema, TestStressUserVersions, ShufflingReplicaListTransformerTest, IndexBasedSpellCheckerTest, BigEndianAscendingWordSerializerTest, CdcrReplicationHandlerTest, TestSQLHandler, TestAuthenticationFramework, VMParamsZkACLAndCredentialsProvidersTest, BlockJoinFacetRandomTest, HdfsUnloadDistributedZkTest, CursorMarkTest, UUIDFieldTest, NumberUtilsTest, SimpleCollectionCreateDeleteTest, TestClusterStateProvider, OpenExchangeRatesOrgProviderTest, CursorPagingTest, PreAnalyzedFieldManagedSchemaCloudTest, AnalyticsMergeStrategyTest, FullSolrCloudDistribCmdsTest, TestSimpleQParserPlugin, TestCollectionAPIs, TestSort, MoveReplicaTest, TestPHPSerializedResponseWriter, HdfsChaosMonkeyNothingIsSafeTest, TestCSVLoader, PeerSyncWithIndexFingerprintCachingTest, TestCustomSort, TestInPlaceUpdatesStandalone, SubstringBytesRefFilterTest, TestSimpleTextCodec, SpellCheckCollatorTest, TestGraphTermsQParserPlugin, TestZkAclsWithHadoopAuth, RAMDirectoryFactoryTest, TestIBSimilarityFactory, CloneFieldUpdateProcessorFactoryTest, HttpPartitionOnCommitTest, AddSchemaFieldsUpdateProcessorFactoryTest, DistributedFacetExistsSmallTest, TestExecutePlanAction, LeaderInitiatedRecoveryOnShardRestartTest, TestUtilizeNode, TestNonDefinedSimilarityFactory, SegmentsInfoRequestHandlerTest, TestRandomFlRTGCloud, ConfigureRecoveryStrategyTest, TestGroupingSearch, TestSubQueryTransformerCrossCore, DistributedQueryElevationComponentTest, CdcrBidirectionalTest, SparseHLLTest, BasicDistributedZkTest, ChaosMonkeySafeLeaderTest, LeaderElectionIntegrationTest, BasicZkTest, RecoveryZkTest, TestReplicationHandler, TestRandomFaceting, LeaderElectionTest, ZkSolrClientTest, ZkCLITest, TestDistributedSearch, ZkControllerTest, TestRealTimeGet, TestReload, TestStressVersions, TestCoreContainer, SimpleFacetsTest, TestSolr4Spatial, StatsComponentTest, SpellCheckComponentTest, PeerSyncTest, ConvertedLegacyTest, TestFiltering, TestFunctionQuery, TestIndexSearcher, HighlighterTest, SimplePostToolTest, TestCoreDiscovery, SuggesterFSTTest, TestFoldingMultitermQuery, TestStressLucene, PolyFieldTest, TestPseudoReturnFields, FieldMutatingUpdateProcessorTest, DirectUpdateHandlerOptimizeTest, SortByFunctionTest, TestRemoteStreaming, TestSolrDeletionPolicy1, TestWriterPerf, DirectSolrSpellCheckerTest, TestQueryTypes, RequestHandlersTest, PathHierarchyTokenizerFactoryTest, TestIndexingPerformance, MoreLikeThisHandlerTest, TestJmxIntegration, ReturnFieldsTest, MBeansHandlerTest, PreAnalyzedFieldTest, DateFieldTest, DOMUtilTest, ClusterStateTest, TestSolrJ, TestUtils, SliceStateTest, SystemInfoHandlerTest, DistributedMLTComponentTest, TestRTGBase, DistributedIntervalFacetingTest, TestCrossCoreJoin, TestCursorMarkWithoutUniqueKey, TestHighlightDedupGrouping, TestSimpleTrackingShardHandler, TestEmbeddedSolrServerAdminHandler, TestEmbeddedSolrServerConstructors, TestEmbeddedSolrServerSchemaAPI, ActionThrottleTest, AddReplicaTest, ChaosMonkeyNothingIsSafeWithPullReplicasTest, DistributedVersionInfoTest, MissingSegmentRecoveryTest, MoveReplicaHDFSTest, RemoteQueryErrorTest, ReplaceNodeNoTargetTest, ReplicationFactorTest, RestartWhileUpdatingTest, RollingRestartTest, TestCloudPseudoReturnFields, TestCloudRecovery, TestPrepRecovery, TestStressInPlaceUpdates, HdfsCollectionsAPIDistributedZkTest, ShardSplitTest, TestShardHandlerFactory, TestSolrConfigHandler, TestConfigReload, V2ApiIntegrationTest, AutoscalingHistoryHandlerTest]
[junit4] Completed [643/777 (2!)] on J0 in 18.86s, 1 test, 1 failure <<< FAILURES!
[...truncated 50606 lines...]