Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Windows/996/
Java: 64bit/jdk1.8.0_131 -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: org.apache.solr.cloud.RecoveryZkTest.test
Error Message:
Mismatch in counts between replicas
Stack Trace:
java.lang.AssertionError: Mismatch in counts between replicas
at
__randomizedtesting.SeedInfo.seed([5C4C16E50C0E8D9A:D418293FA2F2E062]:0)
at org.junit.Assert.fail(Assert.java:93)
at
org.apache.solr.cloud.RecoveryZkTest.assertShardConsistency(RecoveryZkTest.java:143)
at org.apache.solr.cloud.RecoveryZkTest.test(RecoveryZkTest.java:126)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
at
com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
at
com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
at
com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
at
com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at
org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at
org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at
org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at
org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at
org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at
com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at
com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at
com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at
com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at
com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at
com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at
com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at
com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at
com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at
com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at
org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at
com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at
org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at
com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at
com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at
com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at
com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at
com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at
org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at
org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at
org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at
org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at
com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at
com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:748)
Build Log:
[...truncated 11225 lines...]
[junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4] 2> Creating dataDir:
C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001\init-core-data-001
[junit4] 2> 242550 WARN
(SUITE-RecoveryZkTest-seed#[5C4C16E50C0E8D9A]-worker) [ ]
o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=3 numCloses=3
[junit4] 2> 242550 INFO
(SUITE-RecoveryZkTest-seed#[5C4C16E50C0E8D9A]-worker) [ ]
o.a.s.SolrTestCaseJ4 Using PointFields
[junit4] 2> 242554 INFO
(SUITE-RecoveryZkTest-seed#[5C4C16E50C0E8D9A]-worker) [ ]
o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via:
@org.apache.solr.util.RandomizeSSL(reason=, value=NaN, ssl=NaN, clientAuth=NaN)
[junit4] 2> 242556 INFO
(SUITE-RecoveryZkTest-seed#[5C4C16E50C0E8D9A]-worker) [ ]
o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in
C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001\tempDir-001
[junit4] 2> 242557 INFO
(SUITE-RecoveryZkTest-seed#[5C4C16E50C0E8D9A]-worker) [ ]
o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 242557 INFO (Thread-702) [ ] o.a.s.c.ZkTestServer client
port:0.0.0.0/0.0.0.0:0
[junit4] 2> 242557 INFO (Thread-702) [ ] o.a.s.c.ZkTestServer Starting
server
[junit4] 2> 242561 ERROR (Thread-702) [ ] 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> 242658 INFO
(SUITE-RecoveryZkTest-seed#[5C4C16E50C0E8D9A]-worker) [ ]
o.a.s.c.ZkTestServer start zk server on port:61888
[junit4] 2> 242665 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ]
o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from
client sessionid 0x15cd7fc63f50000, likely client has closed socket
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 242669 INFO (jetty-launcher-476-thread-2) [ ]
o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 242669 INFO (jetty-launcher-476-thread-1) [ ]
o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 242670 INFO (jetty-launcher-476-thread-1) [ ]
o.e.j.s.h.ContextHandler Started
o.e.j.s.ServletContextHandler@10cff806{/solr,null,AVAILABLE}
[junit4] 2> 242670 INFO (jetty-launcher-476-thread-2) [ ]
o.e.j.s.h.ContextHandler Started
o.e.j.s.ServletContextHandler@48f9c296{/solr,null,AVAILABLE}
[junit4] 2> 242676 INFO (jetty-launcher-476-thread-2) [ ]
o.e.j.s.AbstractConnector Started
ServerConnector@5832fd1f{HTTP/1.1,[http/1.1]}{127.0.0.1:61892}
[junit4] 2> 242677 INFO (jetty-launcher-476-thread-1) [ ]
o.e.j.s.AbstractConnector Started
ServerConnector@62456480{HTTP/1.1,[http/1.1]}{127.0.0.1:61893}
[junit4] 2> 242677 INFO (jetty-launcher-476-thread-2) [ ]
o.e.j.s.Server Started @245599ms
[junit4] 2> 242679 INFO (jetty-launcher-476-thread-1) [ ]
o.e.j.s.Server Started @245599ms
[junit4] 2> 242679 INFO (jetty-launcher-476-thread-2) [ ]
o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr,
hostPort=61892}
[junit4] 2> 242679 INFO (jetty-launcher-476-thread-1) [ ]
o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr,
hostPort=61893}
[junit4] 2> 242679 ERROR (jetty-launcher-476-thread-2) [ ]
o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be
missing or incomplete.
[junit4] 2> 242679 ERROR (jetty-launcher-476-thread-1) [ ]
o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be
missing or incomplete.
[junit4] 2> 242679 INFO (jetty-launcher-476-thread-2) [ ]
o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version
6.7.0
[junit4] 2> 242679 INFO (jetty-launcher-476-thread-1) [ ]
o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version
6.7.0
[junit4] 2> 242679 INFO (jetty-launcher-476-thread-2) [ ]
o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 242679 INFO (jetty-launcher-476-thread-1) [ ]
o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 242679 INFO (jetty-launcher-476-thread-2) [ ]
o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 242679 INFO (jetty-launcher-476-thread-1) [ ]
o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 242679 INFO (jetty-launcher-476-thread-2) [ ]
o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time:
2017-06-24T02:44:21.228Z
[junit4] 2> 242679 INFO (jetty-launcher-476-thread-1) [ ]
o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time:
2017-06-24T02:44:21.228Z
[junit4] 2> 242685 INFO (jetty-launcher-476-thread-2) [ ]
o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 242685 INFO (jetty-launcher-476-thread-1) [ ]
o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 242695 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ]
o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from
client sessionid 0x15cd7fc63f50002, likely client has closed socket
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 242700 INFO (jetty-launcher-476-thread-2) [ ]
o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params:
socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 242701 INFO (jetty-launcher-476-thread-1) [ ]
o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params:
socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 242702 INFO (jetty-launcher-476-thread-2) [ ]
o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:61888/solr
[junit4] 2> 242702 INFO (jetty-launcher-476-thread-1) [ ]
o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:61888/solr
[junit4] 2> 242731 INFO (jetty-launcher-476-thread-2)
[n:127.0.0.1:61892_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 242731 INFO (jetty-launcher-476-thread-1)
[n:127.0.0.1:61893_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 242732 INFO (jetty-launcher-476-thread-2)
[n:127.0.0.1:61892_solr ] o.a.s.c.OverseerElectionContext I am going to be
the leader 127.0.0.1:61892_solr
[junit4] 2> 242732 INFO (jetty-launcher-476-thread-1)
[n:127.0.0.1:61893_solr ] o.a.s.c.ZkController Register node as live in
ZooKeeper:/live_nodes/127.0.0.1:61893_solr
[junit4] 2> 242733 INFO (jetty-launcher-476-thread-2)
[n:127.0.0.1:61892_solr ] o.a.s.c.Overseer Overseer
(id=98190770904039430-127.0.0.1:61892_solr-n_0000000000) starting
[junit4] 2> 242734 INFO
(zkCallback-488-thread-1-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from
ZooKeeper... (0) -> (1)
[junit4] 2> 242735 INFO
(zkCallback-487-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from
ZooKeeper... (0) -> (1)
[junit4] 2> 242742 INFO (jetty-launcher-476-thread-2)
[n:127.0.0.1:61892_solr ] o.a.s.c.ZkController Register node as live in
ZooKeeper:/live_nodes/127.0.0.1:61892_solr
[junit4] 2> 242743 INFO
(OverseerStateUpdate-98190770904039430-127.0.0.1:61892_solr-n_0000000000)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from
ZooKeeper... (1) -> (2)
[junit4] 2> 242744 INFO
(zkCallback-487-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from
ZooKeeper... (1) -> (2)
[junit4] 2> 242862 INFO (jetty-launcher-476-thread-1)
[n:127.0.0.1:61893_solr ] o.a.s.c.CorePropertiesLocator Found 0 core
definitions underneath
C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001\tempDir-001\node1\.
[junit4] 2> 242863 INFO (jetty-launcher-476-thread-2)
[n:127.0.0.1:61892_solr ] o.a.s.c.CorePropertiesLocator Found 0 core
definitions underneath
C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001\tempDir-001\node2\.
[junit4] 2> 242891 INFO
(SUITE-RecoveryZkTest-seed#[5C4C16E50C0E8D9A]-worker) [ ]
o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 242892 INFO
(SUITE-RecoveryZkTest-seed#[5C4C16E50C0E8D9A]-worker) [ ]
o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:61888/solr ready
[junit4] 2> 242912 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ] o.a.s.SolrTestCaseJ4
###Starting test
[junit4] 2> 242918 INFO (qtp432723822-2523) [n:127.0.0.1:61893_solr ]
o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params
replicationFactor=2&collection.configName=conf&maxShardsPerNode=1&name=recoverytest&action=CREATE&numShards=1&wt=javabin&version=2
and sendToOCPQueue=true
[junit4] 2> 242920 INFO
(OverseerThreadFactory-1025-thread-1-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.CreateCollectionCmd Create collection
recoverytest
[junit4] 2> 243030 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr ]
o.a.s.h.a.CoreAdminOperation core create command
qt=/admin/cores&collection.configName=conf&newCollection=true&name=recoverytest_shard1_replica1&action=CREATE&numShards=1&collection=recoverytest&shard=shard1&wt=javabin&version=2
[junit4] 2> 243034 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr ]
o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647
transient cores
[junit4] 2> 243036 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr ]
o.a.s.h.a.CoreAdminOperation core create command
qt=/admin/cores&collection.configName=conf&newCollection=true&name=recoverytest_shard1_replica2&action=CREATE&numShards=1&collection=recoverytest&shard=shard1&wt=javabin&version=2
[junit4] 2> 243038 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr ]
o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647
transient cores
[junit4] 2> 243144 INFO
(zkCallback-488-thread-1-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 243144 INFO
(zkCallback-487-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 244054 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.SolrConfig
Using Lucene MatchVersion: 6.7.0
[junit4] 2> 244064 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.s.IndexSchema
[recoverytest_shard1_replica1] Schema name=minimal
[junit4] 2> 244067 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.s.IndexSchema
Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 244067 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.CoreContainer
Creating SolrCore 'recoverytest_shard1_replica1' using configuration from
collection recoverytest, trusted=true
[junit4] 2> 244068 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.SolrCore
solr.RecoveryStrategy.Builder
[junit4] 2> 244068 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.SolrCore
[[recoverytest_shard1_replica1] ] Opening new SolrCore at
[C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001\tempDir-001\node2\recoverytest_shard1_replica1],
dataDir=[C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001\tempDir-001\node2\.\recoverytest_shard1_replica1\data\]
[junit4] 2> 244080 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.SolrConfig
Using Lucene MatchVersion: 6.7.0
[junit4] 2> 244086 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.s.IndexSchema
[recoverytest_shard1_replica2] Schema name=minimal
[junit4] 2> 244087 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.s.IndexSchema
Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 244087 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.CoreContainer
Creating SolrCore 'recoverytest_shard1_replica2' using configuration from
collection recoverytest, trusted=true
[junit4] 2> 244092 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.SolrCore
solr.RecoveryStrategy.Builder
[junit4] 2> 244092 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.SolrCore
[[recoverytest_shard1_replica2] ] Opening new SolrCore at
[C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001\tempDir-001\node1\recoverytest_shard1_replica2],
dataDir=[C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001\tempDir-001\node1\.\recoverytest_shard1_replica2\data\]
[junit4] 2> 244167 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.UpdateHandler
Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 244167 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.UpdateLog
Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH
numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 244169 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.CommitTracker
Hard AutoCommit: disabled
[junit4] 2> 244169 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.CommitTracker
Soft AutoCommit: disabled
[junit4] 2> 244180 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1]
o.a.s.s.SolrIndexSearcher Opening
[Searcher@2b415385[recoverytest_shard1_replica1] main]
[junit4] 2> 244183 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1]
o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase:
/configs/conf
[junit4] 2> 244183 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1]
o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using
ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 244183 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1]
o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 244184 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.UpdateLog
Could not find max version in index or recent updates, using new clock
1571052336167518208
[junit4] 2> 244185 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.u.UpdateHandler
Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 244185 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.u.UpdateLog
Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH
numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 244186 INFO
(searcherExecutor-1030-thread-1-processing-n:127.0.0.1:61892_solr
x:recoverytest_shard1_replica1 s:shard1 c:recoverytest) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.SolrCore
[recoverytest_shard1_replica1] Registered new searcher
Searcher@2b415385[recoverytest_shard1_replica1]
main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 244188 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.u.CommitTracker
Hard AutoCommit: disabled
[junit4] 2> 244188 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.u.CommitTracker
Soft AutoCommit: disabled
[junit4] 2> 244189 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2]
o.a.s.s.SolrIndexSearcher Opening
[Searcher@7fd87eac[recoverytest_shard1_replica2] main]
[junit4] 2> 244191 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2]
o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase:
/configs/conf
[junit4] 2> 244191 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2]
o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using
ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 244191 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2]
o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 244191 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1]
o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for
shard shard1: total=2 found=1 timeoutin=9999ms
[junit4] 2> 244191 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.u.UpdateLog
Could not find max version in index or recent updates, using new clock
1571052336174858240
[junit4] 2> 244192 INFO
(searcherExecutor-1031-thread-1-processing-n:127.0.0.1:61893_solr
x:recoverytest_shard1_replica2 s:shard1 c:recoverytest) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.SolrCore
[recoverytest_shard1_replica2] Registered new searcher
Searcher@7fd87eac[recoverytest_shard1_replica2]
main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 244296 INFO
(zkCallback-488-thread-1-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 244296 INFO
(zkCallback-487-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 244692 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1]
o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 244692 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1]
o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 244692 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.SyncStrategy
Sync replicas to http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/
[junit4] 2> 244692 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.PeerSync
PeerSync: core=recoverytest_shard1_replica1 url=http://127.0.0.1:61892/solr
START replicas=[http://127.0.0.1:61893/solr/recoverytest_shard1_replica2/]
nUpdates=100
[junit4] 2> 244692 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.PeerSync
PeerSync: core=recoverytest_shard1_replica1 url=http://127.0.0.1:61892/solr
DONE. We have no versions. sync failed.
[junit4] 2> 244695 INFO (qtp432723822-2525) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.c.S.Request [recoverytest_shard1_replica2] webapp=/solr path=/get
params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2}
status=0 QTime=0
[junit4] 2> 244695 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.SyncStrategy
Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 244695 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1]
o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we
can't sync in that case - we were active before, so become leader anyway
[junit4] 2> 244695 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1]
o.a.s.c.ShardLeaderElectionContext Found all replicas participating in
election, clear LIR
[junit4] 2> 244698 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1]
o.a.s.c.ShardLeaderElectionContext I am the new leader:
http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/ shard1
[junit4] 2> 244802 INFO
(zkCallback-488-thread-1-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 244802 INFO
(zkCallback-487-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 244851 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.ZkController I
am the leader, no recovery necessary
[junit4] 2> 244855 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.s.HttpSolrCall
[admin] webapp=null path=/admin/cores
params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=recoverytest_shard1_replica1&action=CREATE&numShards=1&collection=recoverytest&shard=shard1&wt=javabin&version=2}
status=0 QTime=1825
[junit4] 2> 244956 INFO
(zkCallback-487-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 244956 INFO
(zkCallback-488-thread-1-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 245200 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.s.HttpSolrCall
[admin] webapp=null path=/admin/cores
params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=recoverytest_shard1_replica2&action=CREATE&numShards=1&collection=recoverytest&shard=shard1&wt=javabin&version=2}
status=0 QTime=2164
[junit4] 2> 245203 INFO (qtp432723822-2523) [n:127.0.0.1:61893_solr ]
o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most
30 seconds. Check all shard replicas
[junit4] 2> 245302 INFO
(zkCallback-488-thread-1-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 245302 INFO
(zkCallback-487-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 246205 INFO (qtp432723822-2523) [n:127.0.0.1:61893_solr ]
o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections
params={replicationFactor=2&collection.configName=conf&maxShardsPerNode=1&name=recoverytest&action=CREATE&numShards=1&wt=javabin&version=2}
status=0 QTime=3287
[junit4] 2> 246208 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.c.RecoveryZkTest Indexing 1200 documents
[junit4] 2> 246222 INFO (qtp432723822-2540) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-0
(1571052338292981761)]} 0 4
[junit4] 2> 246222 INFO (qtp432723822-2536) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-0
(1571052338292981760)]} 0 4
[junit4] 2> 246222 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-0
(1571052338292981761)]} 0 11
[junit4] 2> 246222 INFO (qtp1446119144-2528) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-0
(1571052338292981760)]} 0 11
[junit4] 2> 246229 INFO (qtp432723822-2541) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-1
(1571052338305564672)]} 0 2
[junit4] 2> 246230 INFO (qtp432723822-2541) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-1
(1571052338305564673)]} 0 0
[junit4] 2> 246230 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-1
(1571052338305564673)]} 0 7
[junit4] 2> 246230 INFO (qtp1446119144-2526) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-1
(1571052338305564672)]} 0 7
[junit4] 2> 246234 INFO (qtp432723822-2541) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-2
(1571052338316050432)]} 0 0
[junit4] 2> 246234 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-2
(1571052338316050432)]} 0 1
[junit4] 2> 246235 INFO (qtp432723822-2522) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-2
(1571052338316050433)]} 0 0
[junit4] 2> 246238 INFO (qtp1446119144-2539) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-2
(1571052338316050433)]} 0 4
[junit4] 2> 246240 INFO (qtp432723822-2519) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-3
(1571052338319196160)]} 0 0
[junit4] 2> 246240 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-3
(1571052338319196160)]} 0 3
[junit4] 2> 246241 INFO (qtp432723822-2519) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-3
(1571052338323390464)]} 0 0
[junit4] 2> 246241 INFO (qtp1446119144-2539) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-3
(1571052338323390464)]} 0 1
[junit4] 2> 246250 INFO (qtp432723822-2519) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[2-3
(-1571052338329681920)]} 0 3
[junit4] 2> 246250 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-3
(-1571052338329681920)]} 0 5
[junit4] 2> 246252 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[1-3
(-1571052338329681921)]} 0 0
[junit4] 2> 246253 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-3
(-1571052338329681921)]} 0 7
[junit4] 2> 246254 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-4
(1571052338335973376)]} 0 0
[junit4] 2> 246255 INFO (qtp1446119144-2528) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-4
(1571052338335973376)]} 0 2
[junit4] 2> 246258 INFO (qtp432723822-2540) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-4
(1571052338339119104)]} 0 0
[junit4] 2> 246258 INFO (qtp1446119144-2520) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-4
(1571052338339119104)]} 0 3
[junit4] 2> 246259 INFO (qtp432723822-2540) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-5
(1571052338341216256)]} 0 0
[junit4] 2> 246259 INFO (qtp1446119144-2528) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-5
(1571052338341216256)]} 0 2
[junit4] 2> 246261 INFO (qtp432723822-2540) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-5
(1571052338343313408)]} 0 0
[junit4] 2> 246264 INFO (qtp432723822-2541) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-6
(1571052338345410560)]} 0 1
[junit4] 2> 246264 INFO (qtp1446119144-2537) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-6
(1571052338345410560)]} 0 2
[junit4] 2> 246266 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-5
(1571052338343313408)]} 0 7
[junit4] 2> 246269 INFO (qtp432723822-2541) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-7
(1571052338351702016)]} 0 0
[junit4] 2> 246269 INFO (qtp1446119144-2539) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-7
(1571052338351702016)]} 0 2
[junit4] 2> 246271 INFO (qtp432723822-2541) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-6
(1571052338353799168)]} 0 0
[junit4] 2> 246271 INFO (qtp1446119144-2532) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-6
(1571052338353799168)]} 0 1
[junit4] 2> 246274 INFO (qtp432723822-2541) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[2-6
(-1571052338357993473)]} 0 0
[junit4] 2> 246275 INFO (qtp432723822-2541) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-7
(1571052338357993472)]} 0 0
[junit4] 2> 246275 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-6
(-1571052338357993473)]} 0 2
[junit4] 2> 246275 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-7
(1571052338357993472)]} 0 2
[junit4] 2> 246280 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[1-6
(-1571052338363236353)]} 0 0
[junit4] 2> 246281 INFO (qtp1446119144-2520) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-6
(-1571052338363236353)]} 0 2
[junit4] 2> 246281 INFO (qtp432723822-2541) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-8
(1571052338363236352)]} 0 0
[junit4] 2> 246282 INFO (qtp1446119144-2526) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-8
(1571052338363236352)]} 0 4
[junit4] 2> 246285 INFO (qtp432723822-2536) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[2-8
(-1571052338369527808)]} 0 0
[junit4] 2> 246285 INFO (qtp1446119144-2537) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-8
(-1571052338369527808)]} 0 1
[junit4] 2> 246290 INFO (qtp432723822-2540) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-9
(1571052338372673536)]} 0 0
[junit4] 2> 246291 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-9
(1571052338372673536)]} 0 3
[junit4] 2> 246291 INFO (qtp432723822-2536) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-8
(1571052338367430656)]} 0 4
[junit4] 2> 246292 INFO (qtp1446119144-2528) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-8
(1571052338367430656)]} 0 10
[junit4] 2> 246293 INFO (qtp432723822-2522) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-10
(1571052338377916416)]} 0 0
[junit4] 2> 246293 INFO (qtp1446119144-2539) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-10
(1571052338377916416)]} 0 1
[junit4] 2> 246297 INFO (qtp432723822-2522) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[1-8
(-1571052338382110720)]} 0 0
[junit4] 2> 246297 INFO (qtp1446119144-2532) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-8
(-1571052338382110720)]} 0 1
[junit4] 2> 246299 INFO (qtp432723822-2522) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[2-10
(-1571052338382110721)]} 0 0
[junit4] 2> 246299 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-10
(-1571052338382110721)]} 0 2
[junit4] 2> 246303 INFO (qtp432723822-2523) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-9
(1571052338386305024)]} 0 0
[junit4] 2> 246303 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-9
(1571052338386305024)]} 0 3
[junit4] 2> 246305 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-11
(1571052338388402176)]} 0 0
[junit4] 2> 246305 INFO (qtp1446119144-2520) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-11
(1571052338388402176)]} 0 3
[junit4] 2> 246315 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-10
(1571052338392596480)]} 0 8
[junit4] 2> 246316 INFO (qtp1446119144-2526) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-10
(1571052338392596480)]} 0 9
[junit4] 2> 246322 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[2-11
(-1571052338408325120)]} 0 0
[junit4] 2> 246322 INFO (qtp1446119144-2537) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-11
(-1571052338408325120)]} 0 1
[junit4] 2> 246326 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[1-10
(-1571052338410422272)]} 0 0
[junit4] 2> 246326 INFO (qtp1446119144-2537) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-10
(-1571052338410422272)]} 0 3
[junit4] 2> 246329 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-12
(1571052338412519424)]} 0 0
[junit4] 2> 246329 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-12
(1571052338412519424)]} 0 4
[junit4] 2> 246331 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-11
(1571052338415665152)]} 0 0
[junit4] 2> 246331 INFO (qtp1446119144-2537) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-11
(1571052338415665152)]} 0 3
[junit4] 2> 246338 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[1-11
(-1571052338423005184)]} 0 0
[junit4] 2> 246338 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-11
(-1571052338423005184)]} 0 2
[junit4] 2> 246341 INFO (qtp432723822-2521) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-13
(1571052338424053760)]} 0 0
[junit4] 2> 246342 INFO (qtp432723822-2519) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-12
(1571052338429296640)]} 0 0
[junit4] 2> 246342 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-12
(1571052338429296640)]} 0 1
[junit4] 2> 246342 INFO (qtp1446119144-2532) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-13
(1571052338424053760)]} 0 6
[junit4] 2> 246347 INFO (qtp432723822-2519) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-13
(1571052338433490944)]} 0 0
[junit4] 2> 246347 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-13
(1571052338433490944)]} 0 2
[junit4] 2> 246353 INFO (qtp432723822-2519) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-14
(1571052338438733824)]} 0 0
[junit4] 2> 246353 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-14
(1571052338438733824)]} 0 3
[junit4] 2> 246358 INFO (qtp432723822-2541) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-15
(1571052338443976704)]} 0 1
[junit4] 2> 246358 INFO (qtp1446119144-2528) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-15
(1571052338443976704)]} 0 2
[junit4] 2> 246361 INFO (qtp432723822-2518) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-14
(1571052338434539520)]} 0 0
[junit4] 2> 246363 INFO (qtp432723822-2518) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-16
(1571052338449219584)]} 0 0
[junit4] 2> 246363 INFO (qtp1446119144-2537) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-16
(1571052338449219584)]} 0 2
[junit4] 2> 246389 INFO (qtp1446119144-2520) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-14
(1571052338434539520)]} 0 43
[junit4] 2> 246396 INFO (qtp432723822-2518) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-17
(1571052338481725440)]} 0 0
[junit4] 2> 246396 INFO (qtp1446119144-2539) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-17
(1571052338481725440)]} 0 4
[junit4] 2> 246397 INFO (qtp432723822-2518) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-15
(1571052338484871168)]} 0 0
[junit4] 2> 246398 INFO (qtp432723822-2518) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[1-14
(-1571052338488016896)]} 0 0
[junit4] 2> 246398 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-14
(-1571052338488016896)]} 0 1
[junit4] 2> 246420 INFO (qtp1446119144-2516) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-15
(1571052338484871168)]} 0 26
[junit4] 2> 246432 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.e.j.s.AbstractConnector Stopped
ServerConnector@62456480{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 246438 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ] o.a.s.c.CoreContainer
Shutting down CoreContainer instance=923200137
[junit4] 2> 246440 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.m.SolrMetricManager Closing metric reporters for: solr.node
[junit4] 2> 246440 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jvm
[junit4] 2> 246440 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jetty
[junit4] 2> 246445 INFO (coreCloseExecutor-1040-thread-1)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.SolrCore [recoverytest_shard1_replica2]
CLOSING SolrCore org.apache.solr.core.SolrCore@6d831ff1
[junit4] 2> 246445 INFO (coreCloseExecutor-1040-thread-1)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.u.DirectUpdateHandler2 Committing on
IndexWriter close.
[junit4] 2> 246445 INFO (coreCloseExecutor-1040-thread-1)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.u.SolrIndexWriter Calling setCommitData
with IW:org.apache.solr.update.SolrIndexWriter@1b125b59
[junit4] 2> 246450 INFO (coreCloseExecutor-1040-thread-1)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.m.SolrMetricManager Closing metric
reporters for: solr.core.recoverytest.shard1.replica2
[junit4] 2> 246454 WARN
(zkCallback-487-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered,
but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 246456 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.e.j.s.h.ContextHandler Stopped
o.e.j.s.ServletContextHandler@10cff806{/solr,null,UNAVAILABLE}
[junit4] 2> 246456 INFO
(zkCallback-488-thread-1-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from
ZooKeeper... (2) -> (1)
[junit4] 2> 246456 INFO (zkCallback-494-thread-1) [ ]
o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 246545 INFO
(zkCallback-488-thread-1-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [1])
[junit4] 2> 246658 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ] o.e.j.s.Server
jetty-9.3.14.v20161028
[junit4] 2> 246659 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.e.j.s.h.ContextHandler Started
o.e.j.s.ServletContextHandler@32f2a3e0{/solr,null,AVAILABLE}
[junit4] 2> 246660 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.e.j.s.AbstractConnector Started
ServerConnector@72e3aae7{HTTP/1.1,[http/1.1]}{127.0.0.1:61893}
[junit4] 2> 246660 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ] o.e.j.s.Server
Started @249581ms
[junit4] 2> 246661 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr,
hostPort=61893}
[junit4] 2> 246661 ERROR
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be
missing or incomplete.
[junit4] 2> 246662 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version
6.7.0
[junit4] 2> 246662 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 246662 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 246662 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time:
2017-06-24T02:44:25.211Z
[junit4] 2> 246666 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 246680 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ]
o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from
client sessionid 0x15cd7fc63f50009, likely client has closed socket
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 246682 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ]
o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params:
socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 246683 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ] o.a.s.c.ZkContainer
Zookeeper client=127.0.0.1:61888/solr
[junit4] 2> 246688 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ]
o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from
client sessionid 0x15cd7fc63f5000a, likely client has closed socket
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 246699 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [n:127.0.0.1:61893_solr ]
o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 246701 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [n:127.0.0.1:61893_solr ]
o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 246703 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [n:127.0.0.1:61893_solr ]
o.a.s.c.ZkController Register node as live in
ZooKeeper:/live_nodes/127.0.0.1:61893_solr
[junit4] 2> 246705 INFO
(zkCallback-488-thread-1-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from
ZooKeeper... (1) -> (2)
[junit4] 2> 246705 INFO (zkCallback-494-thread-1) [ ]
o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 246707 INFO
(zkCallback-499-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from
ZooKeeper... (1) -> (2)
[junit4] 2> 246783 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [n:127.0.0.1:61893_solr ]
o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath
C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001\tempDir-001\node1\.
[junit4] 2> 246783 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [n:127.0.0.1:61893_solr ]
o.a.s.c.CorePropertiesLocator Cores are: [recoverytest_shard1_replica2]
[junit4] 2> 246798 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.TransientSolrCoreCacheDefault
Allocating transient cache for 2147483647 transient cores
[junit4] 2> 246816 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.SolrConfig Using Lucene MatchVersion:
6.7.0
[junit4] 2> 246833 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.s.IndexSchema
[recoverytest_shard1_replica2] Schema name=minimal
[junit4] 2> 246837 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.s.IndexSchema Loaded schema minimal/1.1
with uniqueid field id
[junit4] 2> 246837 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.CoreContainer Creating SolrCore
'recoverytest_shard1_replica2' using configuration from collection
recoverytest, trusted=true
[junit4] 2> 246837 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 246837 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.SolrCore
[[recoverytest_shard1_replica2] ] Opening new SolrCore at
[C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001\tempDir-001\node1\recoverytest_shard1_replica2],
dataDir=[C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001\tempDir-001\node1\.\recoverytest_shard1_replica2\data\]
[junit4] 2> 246909 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.u.UpdateHandler Using UpdateLog
implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 246909 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.u.UpdateLog Initializing UpdateLog:
dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10
numVersionBuckets=65536
[junit4] 2> 246911 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 246911 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 246912 INFO
(zkCallback-499-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 246912 INFO
(zkCallback-488-thread-2-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader A cluster state change:
[WatchedEvent state:SyncConnected type:NodeDataChanged
path:/collections/recoverytest/state.json] for collection [recoverytest] has
occurred - updating... (live nodes size: [2])
[junit4] 2> 246914 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.s.SolrIndexSearcher Opening
[Searcher@783d97fd[recoverytest_shard1_replica2] main]
[junit4] 2> 246916 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.r.ManagedResourceStorage Configured
ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 246916 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.r.ManagedResourceStorage Loaded null at
path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 246916 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.h.ReplicationHandler Commits will be
reserved for 10000
[junit4] 2> 246917 INFO
(searcherExecutor-1048-thread-1-processing-n:127.0.0.1:61893_solr
x:recoverytest_shard1_replica2 s:shard1 c:recoverytest r:core_node2)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.SolrCore [recoverytest_shard1_replica2]
Registered new searcher Searcher@783d97fd[recoverytest_shard1_replica2]
main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 246917 INFO
(coreLoadExecutor-1047-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.u.UpdateLog Could not find max version in
index or recent updates, using new clock 1571052339033276416
[junit4] 2> 246921 INFO
(coreZkRegister-1042-thread-1-processing-n:127.0.0.1:61893_solr
x:recoverytest_shard1_replica2 s:shard1 c:recoverytest r:core_node2)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.ZkController Core needs to
recover:recoverytest_shard1_replica2
[junit4] 2> 246921 INFO
(updateExecutor-496-thread-1-processing-n:127.0.0.1:61893_solr
x:recoverytest_shard1_replica2 s:shard1 c:recoverytest r:core_node2)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 246921 INFO
(recoveryExecutor-497-thread-1-processing-n:127.0.0.1:61893_solr
x:recoverytest_shard1_replica2 s:shard1 c:recoverytest r:core_node2)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.RecoveryStrategy Starting recovery
process. recoveringAfterStartup=true
[junit4] 2> 246921 INFO
(recoveryExecutor-497-thread-1-processing-n:127.0.0.1:61893_solr
x:recoverytest_shard1_replica2 s:shard1 c:recoverytest r:core_node2)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.RecoveryStrategy ######
startupVersions=[[]]
[junit4] 2> 246921 INFO
(recoveryExecutor-497-thread-1-processing-n:127.0.0.1:61893_solr
x:recoverytest_shard1_replica2 s:shard1 c:recoverytest r:core_node2)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.RecoveryStrategy Begin buffering
updates. core=[recoverytest_shard1_replica2]
[junit4] 2> 246921 INFO
(recoveryExecutor-497-thread-1-processing-n:127.0.0.1:61893_solr
x:recoverytest_shard1_replica2 s:shard1 c:recoverytest r:core_node2)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.u.UpdateLog Starting to buffer updates.
FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 246922 INFO
(recoveryExecutor-497-thread-1-processing-n:127.0.0.1:61893_solr
x:recoverytest_shard1_replica2 s:shard1 c:recoverytest r:core_node2)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.RecoveryStrategy Publishing state of
core [recoverytest_shard1_replica2] as recovering, leader is
[http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/] and I am
[http://127.0.0.1:61893/solr/recoverytest_shard1_replica2/]
[junit4] 2> 246933 INFO (qtp489577843-2599) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-18
(1571052338514231296)]} 0 6
[junit4] 2> 246933 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-18
(1571052338514231296)]} 0 511
[junit4] 2> 246935 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-15
(-1571052339052150784)]} 0 0
[junit4] 2> 246936 INFO
(recoveryExecutor-497-thread-1-processing-n:127.0.0.1:61893_solr
x:recoverytest_shard1_replica2 s:shard1 c:recoverytest r:core_node2)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.RecoveryStrategy Sending prep recovery
command to [http://127.0.0.1:61892/solr]; [WaitForState:
action=PREPRECOVERY&core=recoverytest_shard1_replica1&nodeName=127.0.0.1:61893_solr&coreNodeName=core_node2&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
[junit4] 2> 246939 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-19
(1571052339056345088)]} 0 0
[junit4] 2> 246941 INFO (qtp489577843-2599) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica2]
webapp=/solr path=/update
params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:61892/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-16
(1571052338517377024)]} 0 0
[junit4] 2> 246941 INFO
(OverseerCollectionConfigSetProcessor-98190770904039430-127.0.0.1:61892_solr-n_0000000000)
[n:127.0.0.1:61892_solr ] o.a.s.c.OverseerTaskQueue Response ZK path:
/overseer/collection-queue-work/qnr-0000000000 doesn't exist. Requestor may
have disconnected from ZooKeeper
[junit4] 2> 246942 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-20
(1571052339059490816)]} 0 0
[junit4] 2> 246942 INFO (qtp1446119144-2526) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-16
(1571052338517377024)]} 0 517
[junit4] 2> 246945 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-21
(1571052339062636544)]} 0 0
[junit4] 2> 246947 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-22
(1571052339064733696)]} 0 0
[junit4] 2> 246948 INFO (qtp1446119144-2539) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-17
(1571052339065782272)]} 0 3
[junit4] 2> 246950 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-23
(1571052339067879424)]} 0 0
[junit4] 2> 246951 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-14
(-1571052339068928000)]} 0 0
[junit4] 2> 246957 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-18
(1571052339075219456)]} 0 0
[junit4] 2> 246958 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-24
(1571052339076268032)]} 0 0
[junit4] 2> 246969 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[2-15
(-1571052339087802368)]} 0 0
[junit4] 2> 246970 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-19
(1571052339088850944)]} 0 0
[junit4] 2> 246972 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-25
(1571052339090948096)]} 0 0
[junit4] 2> 246974 INFO (qtp1446119144-2520) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-20
(1571052339093045248)]} 0 1
[junit4] 2> 246979 INFO (qtp1446119144-2520) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-26
(1571052339094093824)]} 0 4
[junit4] 2> 246980 INFO (qtp1446119144-2532) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-21
(1571052339096190976)]} 0 3
[junit4] 2> 246982 INFO (qtp1446119144-2520) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-22
(1571052339101433856)]} 0 0
[junit4] 2> 246983 INFO (qtp1446119144-2520) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-18
(-1571052339102482432)]} 0 0
[junit4] 2> 246985 INFO (qtp1446119144-2520) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-23
(1571052339104579584)]} 0 0
[junit4] 2> 246986 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-27
(1571052339105628160)]} 0 0
[junit4] 2> 246990 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-28
(1571052339108773888)]} 0 0
[junit4] 2> 246990 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-24
(1571052339109822464)]} 0 0
[junit4] 2> 246992 INFO (qtp1446119144-2526) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{delete=[1-21
(-1571052339111919617)]} 0 0
[junit4] 2> 246993 INFO (qtp1446119144-2529) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-25
(1571052339111919616)]} 0 0
[junit4] 2> 246995 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[1-29
(1571052339115065344)]} 0 0
[junit4] 2> 246996 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr
c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1]
o.a.s.u.p.LogUpdateProcessorFactory [recoverytest_shard1_replica1]
webapp=/solr path=/update params={wt=javabin&version=2}{add=[2-26
(1571052339116113920)]} 0 0
[junit4] 2> 246996 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr ]
o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node2, state:
recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true
[junit4] 2> 246997 INFO (qtp1446119144-2530) [n:127.0.0.1:61892_solr ]
o.a.s.h.a.PrepRecoveryOp Will wait a max of 183 seconds to see
recoverytest_shard1_re
[...truncated too long message...]
s={q=*:*&distrib=false&wt=javabin&version=2} hits=421 status=0 QTime=0
[junit4] 2> 250413 INFO (qtp489577843-2601) [n:127.0.0.1:61893_solr
c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2]
o.a.s.c.S.Request [recoverytest_shard1_replica2] webapp=/solr path=/select
params={q=*:*&distrib=false&wt=javabin&version=2} hits=422 status=0 QTime=0
[junit4] 2> 250413 INFO
(TEST-RecoveryZkTest.test-seed#[5C4C16E50C0E8D9A]) [ ] o.a.s.SolrTestCaseJ4
###Ending test
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest
-Dtests.method=test -Dtests.seed=5C4C16E50C0E8D9A -Dtests.slow=true
-Dtests.locale=fi -Dtests.timezone=Asia/Thimbu -Dtests.asserts=true
-Dtests.file.encoding=US-ASCII
[junit4] FAILURE 7.52s J0 | RecoveryZkTest.test <<<
[junit4] > Throwable #1: java.lang.AssertionError: Mismatch in counts
between replicas
[junit4] > at
__randomizedtesting.SeedInfo.seed([5C4C16E50C0E8D9A:D418293FA2F2E062]:0)
[junit4] > at
org.apache.solr.cloud.RecoveryZkTest.assertShardConsistency(RecoveryZkTest.java:143)
[junit4] > at
org.apache.solr.cloud.RecoveryZkTest.test(RecoveryZkTest.java:126)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 250416 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ]
o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from
client sessionid 0x15cd7fc63f50008, likely client has closed socket
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 250419 INFO (jetty-closer-477-thread-1) [ ]
o.e.j.s.AbstractConnector Stopped
ServerConnector@72e3aae7{HTTP/1.1,[http/1.1]}{127.0.0.1:61893}
[junit4] 2> 250421 INFO (jetty-closer-477-thread-1) [ ]
o.a.s.c.CoreContainer Shutting down CoreContainer instance=551655901
[junit4] 2> 250422 INFO (jetty-closer-477-thread-1) [ ]
o.a.s.m.SolrMetricManager Closing metric reporters for: solr.node
[junit4] 2> 250422 INFO (jetty-closer-477-thread-1) [ ]
o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jvm
[junit4] 2> 250422 INFO (jetty-closer-477-thread-1) [ ]
o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jetty
[junit4] 2> 250422 INFO (jetty-closer-477-thread-2) [ ]
o.e.j.s.AbstractConnector Stopped
ServerConnector@5832fd1f{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 250424 INFO (jetty-closer-477-thread-2) [ ]
o.a.s.c.CoreContainer Shutting down CoreContainer instance=763540796
[junit4] 2> 250424 INFO (jetty-closer-477-thread-2) [ ]
o.a.s.m.SolrMetricManager Closing metric reporters for: solr.node
[junit4] 2> 250424 INFO (jetty-closer-477-thread-2) [ ]
o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jvm
[junit4] 2> 250424 INFO (jetty-closer-477-thread-2) [ ]
o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jetty
[junit4] 2> 250439 INFO (coreCloseExecutor-1054-thread-1)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.c.SolrCore [recoverytest_shard1_replica2]
CLOSING SolrCore org.apache.solr.core.SolrCore@23cb1e78
[junit4] 2> 250439 INFO (coreCloseExecutor-1055-thread-1)
[n:127.0.0.1:61892_solr c:recoverytest s:shard1 r:core_node1
x:recoverytest_shard1_replica1] o.a.s.c.SolrCore [recoverytest_shard1_replica1]
CLOSING SolrCore org.apache.solr.core.SolrCore@46b5f55d
[junit4] 2> 250442 INFO (coreCloseExecutor-1055-thread-1)
[n:127.0.0.1:61892_solr c:recoverytest s:shard1 r:core_node1
x:recoverytest_shard1_replica1] o.a.s.m.SolrMetricManager Closing metric
reporters for: solr.core.recoverytest.shard1.replica1
[junit4] 2> 250443 INFO (coreCloseExecutor-1054-thread-1)
[n:127.0.0.1:61893_solr c:recoverytest s:shard1 r:core_node2
x:recoverytest_shard1_replica2] o.a.s.m.SolrMetricManager Closing metric
reporters for: solr.core.recoverytest.shard1.replica2
[junit4] 2> 250445 INFO (jetty-closer-477-thread-2) [ ]
o.a.s.c.Overseer Overseer
(id=98190770904039430-127.0.0.1:61892_solr-n_0000000000) closing
[junit4] 2> 250445 INFO
(OverseerStateUpdate-98190770904039430-127.0.0.1:61892_solr-n_0000000000)
[n:127.0.0.1:61892_solr ] o.a.s.c.Overseer Overseer Loop exiting :
127.0.0.1:61892_solr
[junit4] 2> 250449 WARN
(zkCallback-488-thread-2-processing-n:127.0.0.1:61892_solr)
[n:127.0.0.1:61892_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered,
but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 250449 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ]
o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from
client sessionid 0x15cd7fc63f50006, likely client has closed socket
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 250449 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ]
o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from
client sessionid 0x15cd7fc63f5000b, likely client has closed socket
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 250451 INFO (jetty-closer-477-thread-2) [ ]
o.e.j.s.h.ContextHandler Stopped
o.e.j.s.ServletContextHandler@48f9c296{/solr,null,UNAVAILABLE}
[junit4] 2> 251949 WARN
(zkCallback-499-thread-1-processing-n:127.0.0.1:61893_solr)
[n:127.0.0.1:61893_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered,
but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 251950 INFO (jetty-closer-477-thread-1) [ ]
o.e.j.s.h.ContextHandler Stopped
o.e.j.s.ServletContextHandler@32f2a3e0{/solr,null,UNAVAILABLE}
[junit4] 2> 251951 ERROR
(SUITE-RecoveryZkTest-seed#[5C4C16E50C0E8D9A]-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> 251951 INFO
(SUITE-RecoveryZkTest-seed#[5C4C16E50C0E8D9A]-worker) [ ]
o.a.s.c.ZkTestServer connecting to 127.0.0.1:61888 61888
[junit4] 2> 251953 INFO (Thread-702) [ ] o.a.s.c.ZkTestServer
connecting to 127.0.0.1:61888 61888
[junit4] 2> 251954 WARN (Thread-702) [ ] o.a.s.c.ZkTestServer Watch
limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 4 /solr/aliases.json
[junit4] 2> 4 /solr/clusterprops.json
[junit4] 2> 3 /solr/security.json
[junit4] 2> 3 /solr/configs/conf
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 4 /solr/collections/recoverytest/state.json
[junit4] 2> 4 /solr/clusterstate.json
[junit4] 2> 2
/solr/overseer_elect/election/98190770904039430-127.0.0.1:61892_solr-n_0000000000
[junit4] 2> 2
/solr/collections/recoverytest/leader_elect/shard1/election/98190770904039430-core_node1-n_0000000000
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 4 /solr/collections
[junit4] 2> 3 /solr/live_nodes
[junit4] 2>
[junit4] 2> 251954 INFO
(SUITE-RecoveryZkTest-seed#[5C4C16E50C0E8D9A]-worker) [ ]
o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at:
C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J0\temp\solr.cloud.RecoveryZkTest_5C4C16E50C0E8D9A-001
[junit4] 2> Jun 24, 2017 2:44:30 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=FastCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=FAST,
chunkSize=3, maxDocsPerChunk=784, blockSize=524),
termVectorsFormat=CompressingTermVectorsFormat(compressionMode=FAST,
chunkSize=3, blockSize=524)), sim=RandomSimilarity(queryNorm=true,coord=crazy):
{}, locale=fi, timezone=Asia/Thimbu
[junit4] 2> NOTE: Windows 10 10.0 amd64/Oracle Corporation 1.8.0_131
(64-bit)/cpus=3,threads=1,free=36085496,total=178089984
[junit4] 2> NOTE: All tests run in this JVM: [TestLockTree,
TestSlowCompositeReaderWrapper, CloneFieldUpdateProcessorFactoryTest,
TestFieldCacheSortRandom, TestLRUStatsCache, TestUtils,
TestSchemaVersionResource, UUIDFieldTest, TestDynamicFieldResource,
TestExactSharedStatsCache, CursorPagingTest, DirectoryFactoryTest,
TemplateUpdateProcessorTest, TestSubQueryTransformerDistrib,
SolrGraphiteReporterTest, SegmentsInfoRequestHandlerTest,
TestConfigSetsAPIExclusivity, SolrIndexMetricsTest, ReplicationFactorTest,
SliceStateTest, TestTrieFacet, TestTolerantUpdateProcessorRandomCloud,
TestFieldCacheWithThreads, DistributedFacetPivotLongTailTest, UpdateParamsTest,
SolrTestCaseJ4Test, XmlUpdateRequestHandlerTest, TestConfig, SimpleFacetsTest,
TestLeaderElectionWithEmptyReplica, TestNoOpRegenerator,
TestSolrCoreProperties, RulesTest, TestSystemIdResolver, TestCryptoKeys,
BadCopyFieldTest, HighlighterConfigTest, RecoveryZkTest]
[junit4] Completed [79/713 (1!)] on J0 in 9.93s, 1 test, 1 failure <<<
FAILURES!
[...truncated 45665 lines...]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
