You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2016/11/27 05:17:28 UTC
[JENKINS] Lucene-Solr-6.x-Solaris (64bit/jdk1.8.0) - Build # 517 -
Still Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Solaris/517/
Java: 64bit/jdk1.8.0 -XX:+UseCompressedOops -XX:+UseSerialGC
1 tests failed.
FAILED: org.apache.solr.cloud.CdcrBootstrapTest.testBootstrapWithSourceCluster
Error Message:
Document mismatch on target after sync expected:<20000> but was:<10000>
Stack Trace:
java.lang.AssertionError: Document mismatch on target after sync expected:<20000> but was:<10000>
at __randomizedtesting.SeedInfo.seed([8ECD054F4BAB207A:579B548B48CF3330]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.apache.solr.cloud.CdcrBootstrapTest.testBootstrapWithSourceCluster(CdcrBootstrapTest.java:232)
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:367)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:811)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:462)
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:367)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 12164 lines...]
[junit4] Suite: org.apache.solr.cloud.CdcrBootstrapTest
[junit4] 2> Creating dataDir: /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.CdcrBootstrapTest_8ECD054F4BAB207A-001/init-core-data-001
[junit4] 2> 1833621 INFO (SUITE-CdcrBootstrapTest-seed#[8ECD054F4BAB207A]-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> 1833623 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[8ECD054F4BAB207A]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testBootstrapWithSourceCluster
[junit4] 2> 1833623 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[8ECD054F4BAB207A]) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 1 servers in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.CdcrBootstrapTest_8ECD054F4BAB207A-001/cdcr-target-001
[junit4] 2> 1833623 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[8ECD054F4BAB207A]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 1833623 INFO (Thread-5771) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1833623 INFO (Thread-5771) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 1833723 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[8ECD054F4BAB207A]) [ ] o.a.s.c.ZkTestServer start zk server on port:44817
[junit4] 2> 1833732 INFO (jetty-launcher-3131-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1833734 INFO (jetty-launcher-3131-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@11bf33bd{/solr,null,AVAILABLE}
[junit4] 2> 1833734 INFO (jetty-launcher-3131-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@76e454d0{HTTP/1.1,[http/1.1]}{127.0.0.1:49615}
[junit4] 2> 1833735 INFO (jetty-launcher-3131-thread-1) [ ] o.e.j.s.Server Started @1837751ms
[junit4] 2> 1833735 INFO (jetty-launcher-3131-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=49615}
[junit4] 2> 1833735 ERROR (jetty-launcher-3131-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1833735 INFO (jetty-launcher-3131-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 1833735 INFO (jetty-launcher-3131-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1833735 INFO (jetty-launcher-3131-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1833735 INFO (jetty-launcher-3131-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-11-27T04:42:44.591Z
[junit4] 2> 1833738 INFO (jetty-launcher-3131-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1833745 INFO (jetty-launcher-3131-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1833745 INFO (jetty-launcher-3131-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:44817/solr
[junit4] 2> 1833782 INFO (jetty-launcher-3131-thread-1) [n:127.0.0.1:49615_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:49615_solr
[junit4] 2> 1833783 INFO (jetty-launcher-3131-thread-1) [n:127.0.0.1:49615_solr ] o.a.s.c.Overseer Overseer (id=97007813557026819-127.0.0.1:49615_solr-n_0000000000) starting
[junit4] 2> 1833794 INFO (jetty-launcher-3131-thread-1) [n:127.0.0.1:49615_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49615_solr
[junit4] 2> 1833797 INFO (OverseerStateUpdate-97007813557026819-127.0.0.1:49615_solr-n_0000000000) [n:127.0.0.1:49615_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1833878 INFO (jetty-launcher-3131-thread-1) [n:127.0.0.1:49615_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.CdcrBootstrapTest_8ECD054F4BAB207A-001/cdcr-target-001/node1/.
[junit4] 1> Target zkHost = 127.0.0.1:44817/solr
[junit4] 2> 1833886 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[8ECD054F4BAB207A]) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 1 servers in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.CdcrBootstrapTest_8ECD054F4BAB207A-001/cdcr-source-001
[junit4] 2> 1833887 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[8ECD054F4BAB207A]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 1833887 INFO (Thread-5781) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1833887 INFO (Thread-5781) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 1833890 WARN (Thread-5781) [ ] o.a.z.j.MBeanRegistry Failed to register MBean StandaloneServer_port-1
[junit4] 2> 1833890 WARN (Thread-5781) [ ] o.a.z.s.ZooKeeperServer Failed to register with JMX
[junit4] 2> javax.management.InstanceAlreadyExistsException: org.apache.ZooKeeperService:name0=StandaloneServer_port-1
[junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
[junit4] 2> at org.apache.zookeeper.jmx.MBeanRegistry.register(MBeanRegistry.java:96)
[junit4] 2> at org.apache.zookeeper.server.ZooKeeperServer.registerJMX(ZooKeeperServer.java:377)
[junit4] 2> at org.apache.zookeeper.server.ZooKeeperServer.startup(ZooKeeperServer.java:410)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.startup(NIOServerCnxnFactory.java:123)
[junit4] 2> at org.apache.solr.cloud.ZkTestServer$ZKServerMain.runFromConfig(ZkTestServer.java:308)
[junit4] 2> at org.apache.solr.cloud.ZkTestServer$2.run(ZkTestServer.java:490)
[junit4] 2> 1833988 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[8ECD054F4BAB207A]) [ ] o.a.s.c.ZkTestServer start zk server on port:44332
[junit4] 2> 1833997 INFO (jetty-launcher-3142-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1833999 INFO (jetty-launcher-3142-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@dd0ffe1{/solr,null,AVAILABLE}
[junit4] 2> 1833999 INFO (jetty-launcher-3142-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@5a259fee{HTTP/1.1,[http/1.1]}{127.0.0.1:50243}
[junit4] 2> 1833999 INFO (jetty-launcher-3142-thread-1) [ ] o.e.j.s.Server Started @1838016ms
[junit4] 2> 1833999 INFO (jetty-launcher-3142-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=50243}
[junit4] 2> 1834000 ERROR (jetty-launcher-3142-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1834000 INFO (jetty-launcher-3142-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 1834000 INFO (jetty-launcher-3142-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1834000 INFO (jetty-launcher-3142-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1834000 INFO (jetty-launcher-3142-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-11-27T04:42:44.856Z
[junit4] 2> 1834003 INFO (jetty-launcher-3142-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1834008 INFO (jetty-launcher-3142-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1834009 INFO (jetty-launcher-3142-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:44332/solr
[junit4] 2> 1834045 INFO (jetty-launcher-3142-thread-1) [n:127.0.0.1:50243_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:50243_solr
[junit4] 2> 1834047 INFO (jetty-launcher-3142-thread-1) [n:127.0.0.1:50243_solr ] o.a.s.c.Overseer Overseer (id=97007813574262787-127.0.0.1:50243_solr-n_0000000000) starting
[junit4] 2> 1834062 INFO (jetty-launcher-3142-thread-1) [n:127.0.0.1:50243_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50243_solr
[junit4] 2> 1834064 INFO (zkCallback-3148-thread-1-processing-n:127.0.0.1:50243_solr) [n:127.0.0.1:50243_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1834302 INFO (jetty-launcher-3142-thread-1) [n:127.0.0.1:50243_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.CdcrBootstrapTest_8ECD054F4BAB207A-001/cdcr-source-001/node1/.
[junit4] 2> 1834325 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[8ECD054F4BAB207A]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1834328 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[8ECD054F4BAB207A]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:44332/solr ready
[junit4] 2> 1834330 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=cdcr-source&name=cdcr-source&action=CREATE&numShards=1&property.solr.directoryFactory=solr.StandardDirectoryFactory&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 1834333 INFO (OverseerThreadFactory-8364-thread-1-processing-n:127.0.0.1:50243_solr) [n:127.0.0.1:50243_solr ] o.a.s.c.CreateCollectionCmd Create collection cdcr-source
[junit4] 2> 1834441 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=cdcr-source&newCollection=true&name=cdcr-source_shard1_replica1&action=CREATE&numShards=1&collection=cdcr-source&shard=shard1&property.solr.directoryFactory=solr.StandardDirectoryFactory&wt=javabin&version=2
[junit4] 2> 1834551 INFO (zkCallback-3148-thread-2-processing-n:127.0.0.1:50243_solr) [n:127.0.0.1:50243_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/cdcr-source/state.json] for collection [cdcr-source] has occurred - updating... (live nodes size: [1])
[junit4] 2> 1835455 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 1835481 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.s.ManagedIndexSchemaFactory The schema is configured as managed, but managed schema resource managed-schema not found - loading non-managed schema schema.xml instead
[junit4] 2> 1835483 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.s.IndexSchema [cdcr-source_shard1_replica1] Schema name=minimal
[junit4] 2> 1835485 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 1835486 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.s.ManagedIndexSchema Created and persisted managed schema znode at /configs/cdcr-source/managed-schema
[junit4] 2> 1835492 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.s.ManagedIndexSchemaFactory After upgrading to managed schema in ZooKeeper, renamed the non-managed schema /configs/cdcr-source/schema.xml to /configs/cdcr-source/schema.xml.bak
[junit4] 2> 1835493 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.CoreContainer Creating SolrCore 'cdcr-source_shard1_replica1' using configuration from collection cdcr-source
[junit4] 2> 1835493 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [[cdcr-source_shard1_replica1] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.CdcrBootstrapTest_8ECD054F4BAB207A-001/cdcr-source-001/node1/cdcr-source_shard1_replica1], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.CdcrBootstrapTest_8ECD054F4BAB207A-001/cdcr-source-001/node1/./cdcr-source_shard1_replica1/data/]
[junit4] 2> 1835534 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.CdcrUpdateLog
[junit4] 2> 1835534 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1835535 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1835535 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1835536 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@64fa6088[cdcr-source_shard1_replica1] main]
[junit4] 2> 1835538 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/cdcr-source
[junit4] 2> 1835540 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/cdcr-source
[junit4] 2> 1835540 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/cdcr-source/managed-schema
[junit4] 2> 1835541 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1835546 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.h.CdcrBufferStateManager Created znode /collections/cdcr-source/cdcr/state/buffer
[junit4] 2> 1835548 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.h.CdcrProcessStateManager Created znode /collections/cdcr-source/cdcr/state/process
[junit4] 2> 1835556 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@64fa6088[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1835556 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1552125018937229312
[junit4] 2> 1835571 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1835571 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1835571 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:50243/solr/cdcr-source_shard1_replica1/
[junit4] 2> 1835571 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1835571 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SyncStrategy http://127.0.0.1:50243/solr/cdcr-source_shard1_replica1/ has no replicas
[junit4] 2> 1835579 INFO (zkCallback-3148-thread-1-processing-n:127.0.0.1:50243_solr) [n:127.0.0.1:50243_solr ] o.a.s.h.CdcrLeaderStateManager Received new leader state @ cdcr-source:shard1
[junit4] 2> 1835580 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:50243/solr/cdcr-source_shard1_replica1/ shard1
[junit4] 2> 1835691 INFO (zkCallback-3148-thread-1-processing-n:127.0.0.1:50243_solr) [n:127.0.0.1:50243_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/cdcr-source/state.json] for collection [cdcr-source] has occurred - updating... (live nodes size: [1])
[junit4] 2> 1835735 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1835738 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=cdcr-source&newCollection=true&name=cdcr-source_shard1_replica1&action=CREATE&numShards=1&collection=cdcr-source&shard=shard1&property.solr.directoryFactory=solr.StandardDirectoryFactory&wt=javabin&version=2} status=0 QTime=1297
[junit4] 2> 1835742 INFO (qtp195912523-18627) [n:127.0.0.1:50243_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> 1835847 INFO (zkCallback-3148-thread-1-processing-n:127.0.0.1:50243_solr) [n:127.0.0.1:50243_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/cdcr-source/state.json] for collection [cdcr-source] has occurred - updating... (live nodes size: [1])
[junit4] 2> 1836339 INFO (OverseerCollectionConfigSetProcessor-97007813574262787-127.0.0.1:50243_solr-n_0000000000) [n:127.0.0.1:50243_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> 1836743 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=cdcr-source&name=cdcr-source&action=CREATE&numShards=1&property.solr.directoryFactory=solr.StandardDirectoryFactory&wt=javabin&version=2} status=0 QTime=2414
[junit4] 1> Adding 100 docs with commit=true, numDocs=100
[junit4] 2> 1836755 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=7
[junit4] 2> 1836757 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1836757 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1836778 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@66096a2[cdcr-source_shard1_replica1] main]
[junit4] 2> 1836779 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@66096a2[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C100)))}
[junit4] 2> 1836779 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1836779 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=21
[junit4] 1> Adding 100 docs with commit=true, numDocs=200
[junit4] 2> 1836787 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=5
[junit4] 2> 1836790 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1836790 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1836812 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@2a4b2f3[cdcr-source_shard1_replica1] main]
[junit4] 2> 1836812 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@2a4b2f3[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C100) Uninverting(_1(6.4.0):C100)))}
[junit4] 2> 1836812 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1836813 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=22
[junit4] 1> Adding 100 docs with commit=true, numDocs=300
[junit4] 2> 1836819 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=4
[junit4] 2> 1836821 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1836821 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1836842 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@26058c51[cdcr-source_shard1_replica1] main]
[junit4] 2> 1836843 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1836843 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@26058c51[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C100) Uninverting(_1(6.4.0):C100) Uninverting(_2(6.4.0):C100)))}
[junit4] 2> 1836843 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=21
[junit4] 1> Adding 100 docs with commit=true, numDocs=400
[junit4] 2> 1836851 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=4
[junit4] 2> 1836854 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1836854 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1836880 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@ca73bcc[cdcr-source_shard1_replica1] main]
[junit4] 2> 1836880 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@ca73bcc[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C100) Uninverting(_1(6.4.0):C100) Uninverting(_2(6.4.0):C100) Uninverting(_3(6.4.0):C100)))}
[junit4] 2> 1836880 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1836881 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=27
[junit4] 1> Adding 100 docs with commit=true, numDocs=500
[junit4] 2> 1836888 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=4
[junit4] 2> 1836896 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1836896 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1836923 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@78ffab88[cdcr-source_shard1_replica1] main]
[junit4] 2> 1836923 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@78ffab88[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C100) Uninverting(_1(6.4.0):C100) Uninverting(_2(6.4.0):C100) Uninverting(_3(6.4.0):C100) Uninverting(_4(6.4.0):C100)))}
[junit4] 2> 1836923 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1836923 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=27
[junit4] 1> Adding 100 docs with commit=true, numDocs=600
[junit4] 2> 1836932 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=4
[junit4] 2> 1836934 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1836934 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1836961 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1e80d1ed[cdcr-source_shard1_replica1] main]
[junit4] 2> 1836962 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1836962 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@1e80d1ed[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C100) Uninverting(_1(6.4.0):C100) Uninverting(_2(6.4.0):C100) Uninverting(_3(6.4.0):C100) Uninverting(_4(6.4.0):C100) Uninverting(_5(6.4.0):C100)))}
[junit4] 2> 1836962 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=28
[junit4] 1> Adding 100 docs with commit=true, numDocs=700
[junit4] 2> 1836968 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 1836980 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1836980 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837008 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@36e1e70c[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837009 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837009 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@36e1e70c[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C100) Uninverting(_1(6.4.0):C100) Uninverting(_2(6.4.0):C100) Uninverting(_3(6.4.0):C100) Uninverting(_4(6.4.0):C100) Uninverting(_5(6.4.0):C100) Uninverting(_6(6.4.0):C100)))}
[junit4] 2> 1837009 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=29
[junit4] 1> Adding 100 docs with commit=true, numDocs=800
[junit4] 2> 1837018 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 1837021 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837021 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837052 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1faa6974[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837052 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837052 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@1faa6974[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C100) Uninverting(_1(6.4.0):C100) Uninverting(_2(6.4.0):C100) Uninverting(_3(6.4.0):C100) Uninverting(_4(6.4.0):C100) Uninverting(_5(6.4.0):C100) Uninverting(_6(6.4.0):C100) Uninverting(_7(6.4.0):C100)))}
[junit4] 2> 1837053 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=31
[junit4] 1> Adding 100 docs with commit=true, numDocs=900
[junit4] 2> 1837060 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 1837063 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837063 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837092 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@52e33ddb[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837093 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837093 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@52e33ddb[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C100) Uninverting(_1(6.4.0):C100) Uninverting(_2(6.4.0):C100) Uninverting(_3(6.4.0):C100) Uninverting(_4(6.4.0):C100) Uninverting(_5(6.4.0):C100) Uninverting(_6(6.4.0):C100) Uninverting(_7(6.4.0):C100) Uninverting(_8(6.4.0):C100)))}
[junit4] 2> 1837093 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=30
[junit4] 1> Adding 100 docs with commit=true, numDocs=1000
[junit4] 2> 1837100 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 1837102 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837102 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837137 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@6d7dc570[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837138 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837138 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@6d7dc570[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C100) Uninverting(_1(6.4.0):C100) Uninverting(_2(6.4.0):C100) Uninverting(_3(6.4.0):C100) Uninverting(_4(6.4.0):C100) Uninverting(_5(6.4.0):C100) Uninverting(_6(6.4.0):C100) Uninverting(_7(6.4.0):C100) Uninverting(_8(6.4.0):C100) Uninverting(_9(6.4.0):C100)))}
[junit4] 2> 1837138 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=36
[junit4] 1> Adding 100 docs with commit=true, numDocs=1100
[junit4] 2> 1837146 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 1837151 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837151 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837183 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@5ce0e331[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837184 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@5ce0e331[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.4.0):C1000) Uninverting(_b(6.4.0):C100)))}
[junit4] 2> 1837184 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837209 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=59
[junit4] 1> Adding 100 docs with commit=true, numDocs=1200
[junit4] 2> 1837214 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 1837216 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837216 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837240 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@5e28e49d[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837241 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837241 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@5e28e49d[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.4.0):C1000) Uninverting(_b(6.4.0):C100) Uninverting(_c(6.4.0):C100)))}
[junit4] 2> 1837241 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=24
[junit4] 1> Adding 100 docs with commit=true, numDocs=1300
[junit4] 2> 1837245 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 1837248 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837248 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837275 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@3377924a[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837276 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@3377924a[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.4.0):C1000) Uninverting(_b(6.4.0):C100) Uninverting(_c(6.4.0):C100) Uninverting(_d(6.4.0):C100)))}
[junit4] 2> 1837276 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837276 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=28
[junit4] 1> Adding 100 docs with commit=true, numDocs=1400
[junit4] 2> 1837281 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 1837285 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837286 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837316 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@14d21765[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837316 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@14d21765[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.4.0):C1000) Uninverting(_b(6.4.0):C100) Uninverting(_c(6.4.0):C100) Uninverting(_d(6.4.0):C100) Uninverting(_e(6.4.0):C100)))}
[junit4] 2> 1837316 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837317 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=31
[junit4] 1> Adding 100 docs with commit=true, numDocs=1500
[junit4] 2> 1837324 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 1837327 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837327 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837355 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1d9db59b[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837355 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837355 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@1d9db59b[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.4.0):C1000) Uninverting(_b(6.4.0):C100) Uninverting(_c(6.4.0):C100) Uninverting(_d(6.4.0):C100) Uninverting(_e(6.4.0):C100) Uninverting(_f(6.4.0):C100)))}
[junit4] 2> 1837356 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=28
[junit4] 1> Adding 100 docs with commit=true, numDocs=1600
[junit4] 2> 1837362 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 1837364 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837364 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837397 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@436ed90f[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837398 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837398 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@436ed90f[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.4.0):C1000) Uninverting(_b(6.4.0):C100) Uninverting(_c(6.4.0):C100) Uninverting(_d(6.4.0):C100) Uninverting(_e(6.4.0):C100) Uninverting(_f(6.4.0):C100) Uninverting(_g(6.4.0):C100)))}
[junit4] 2> 1837399 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=35
[junit4] 1> Adding 100 docs with commit=true, numDocs=1700
[junit4] 2> 1837407 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 1837410 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837410 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837460 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1d4de339[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837460 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837461 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@1d4de339[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.4.0):C1000) Uninverting(_b(6.4.0):C100) Uninverting(_c(6.4.0):C100) Uninverting(_d(6.4.0):C100) Uninverting(_e(6.4.0):C100) Uninverting(_f(6.4.0):C100) Uninverting(_g(6.4.0):C100) Uninverting(_h(6.4.0):C100)))}
[junit4] 2> 1837465 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=55
[junit4] 1> Adding 100 docs with commit=true, numDocs=1800
[junit4] 2> 1837473 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=4
[junit4] 2> 1837475 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837475 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837523 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@d68123d[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837523 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837523 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@d68123d[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.4.0):C1000) Uninverting(_b(6.4.0):C100) Uninverting(_c(6.4.0):C100) Uninverting(_d(6.4.0):C100) Uninverting(_e(6.4.0):C100) Uninverting(_f(6.4.0):C100) Uninverting(_g(6.4.0):C100) Uninverting(_h(6.4.0):C100) Uninverting(_i(6.4.0):C100)))}
[junit4] 2> 1837524 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=48
[junit4] 1> Adding 100 docs with commit=true, numDocs=1900
[junit4] 2> 1837530 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 1837532 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837532 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837577 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@ab8bee9[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837578 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837578 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@ab8bee9[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.4.0):C1000) Uninverting(_b(6.4.0):C100) Uninverting(_c(6.4.0):C100) Uninverting(_d(6.4.0):C100) Uninverting(_e(6.4.0):C100) Uninverting(_f(6.4.0):C100) Uninverting(_g(6.4.0):C100) Uninverting(_h(6.4.0):C100) Uninverting(_i(6.4.0):C100) Uninverting(_j(6.4.0):C100)))}
[junit4] 2> 1837578 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=46
[junit4] 1> Adding 100 docs with commit=true, numDocs=2000
[junit4] 2> 1837588 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=6
[junit4] 2> 1837591 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837591 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837628 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@47fc386e[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837628 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@47fc386e[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_k(6.4.0):C1900) Uninverting(_l(6.4.0):C100)))}
[junit4] 2> 1837628 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837655 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=63
[junit4] 1> Adding 100 docs with commit=true, numDocs=2100
[junit4] 2> 1837660 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 1837662 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837662 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837686 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@7fda187f[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837686 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@7fda187f[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_k(6.4.0):C1900) Uninverting(_l(6.4.0):C100) Uninverting(_m(6.4.0):C100)))}
[junit4] 2> 1837686 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837687 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=24
[junit4] 1> Adding 100 docs with commit=true, numDocs=2200
[junit4] 2> 1837693 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 1837695 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837695 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837722 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@41b9e969[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837722 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837722 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@41b9e969[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_k(6.4.0):C1900) Uninverting(_l(6.4.0):C100) Uninverting(_m(6.4.0):C100) Uninverting(_n(6.4.0):C100)))}
[junit4] 2> 1837722 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=27
[junit4] 1> Adding 100 docs with commit=true, numDocs=2300
[junit4] 2> 1837729 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 1837731 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837731 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837756 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@3b3465a7[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837757 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837757 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@3b3465a7[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_k(6.4.0):C1900) Uninverting(_l(6.4.0):C100) Uninverting(_m(6.4.0):C100) Uninverting(_n(6.4.0):C100) Uninverting(_o(6.4.0):C100)))}
[junit4] 2> 1837757 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=26
[junit4] 1> Adding 100 docs with commit=true, numDocs=2400
[junit4] 2> 1837766 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 1837769 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837769 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837797 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@3b79aac4[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837797 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837797 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@3b79aac4[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_k(6.4.0):C1900) Uninverting(_l(6.4.0):C100) Uninverting(_m(6.4.0):C100) Uninverting(_n(6.4.0):C100) Uninverting(_o(6.4.0):C100) Uninverting(_p(6.4.0):C100)))}
[junit4] 2> 1837797 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=28
[junit4] 1> Adding 100 docs with commit=true, numDocs=2500
[junit4] 2> 1837802 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 1837804 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837804 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837834 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1d694d39[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837835 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@1d694d39[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_k(6.4.0):C1900) Uninverting(_l(6.4.0):C100) Uninverting(_m(6.4.0):C100) Uninverting(_n(6.4.0):C100) Uninverting(_o(6.4.0):C100) Uninverting(_p(6.4.0):C100) Uninverting(_q(6.4.0):C100)))}
[junit4] 2> 1837835 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837835 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=31
[junit4] 1> Adding 100 docs with commit=true, numDocs=2600
[junit4] 2> 1837839 INFO (qtp195912523-18631) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=2
[junit4] 2> 1837846 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837846 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837878 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1e2b367b[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837879 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837879 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@1e2b367b[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_k(6.4.0):C1900) Uninverting(_l(6.4.0):C100) Uninverting(_m(6.4.0):C100) Uninverting(_n(6.4.0):C100) Uninverting(_o(6.4.0):C100) Uninverting(_p(6.4.0):C100) Uninverting(_q(6.4.0):C100) Uninverting(_r(6.4.0):C100)))}
[junit4] 2> 1837880 INFO (qtp195912523-18625) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=34
[junit4] 1> Adding 100 docs with commit=true, numDocs=2700
[junit4] 2> 1837886 INFO (qtp195912523-18632) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 1837888 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837888 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837920 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@7f07cf95[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837920 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@7f07cf95[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_k(6.4.0):C1900) Uninverting(_l(6.4.0):C100) Uninverting(_m(6.4.0):C100) Uninverting(_n(6.4.0):C100) Uninverting(_o(6.4.0):C100) Uninverting(_p(6.4.0):C100) Uninverting(_q(6.4.0):C100) Uninverting(_r(6.4.0):C100) Uninverting(_s(6.4.0):C100)))}
[junit4] 2> 1837920 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1837920 INFO (qtp195912523-18628) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=32
[junit4] 1> Adding 100 docs with commit=true, numDocs=2800
[junit4] 2> 1837932 INFO (qtp195912523-18629) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=5
[junit4] 2> 1837934 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1837934 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1837997 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1dc160cb[cdcr-source_shard1_replica1] main]
[junit4] 2> 1837998 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1838000 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@1dc160cb[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_k(6.4.0):C1900) Uninverting(_l(6.4.0):C100) Uninverting(_m(6.4.0):C100) Uninverting(_n(6.4.0):C100) Uninverting(_o(6.4.0):C100) Uninverting(_p(6.4.0):C100) Uninverting(_q(6.4.0):C100) Uninverting(_r(6.4.0):C100) Uninverting(_s(6.4.0):C100) Uninverting(_t(6.4.0):C100)))}
[junit4] 2> 1838000 INFO (qtp195912523-18627) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=65
[junit4] 1> Adding 100 docs with commit=true, numDocs=2900
[junit4] 2> 1838005 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.S.Request [cdcr-source_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-source:3&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 1838008 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1838008 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@113f07e9
[junit4] 2> 1838055 INFO (qtp195912523-18630) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@7b81e6a1[cdcr-source_shard1_replica1] main]
[junit4] 2> 1838055 INFO (searcherExecutor-8367-thread-1-processing-n:127.0.0.1:50243_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:50243_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCo
[...truncated too long message...]
nodes
[junit4] 2>
[junit4] 2> 2020093 INFO (jetty-launcher-3196-thread-1) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@23773c1e{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 2020094 INFO (jetty-launcher-3196-thread-1) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=2066041936
[junit4] 2> 2020097 INFO (coreCloseExecutor-8543-thread-1) [n:127.0.0.1:63903_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.SolrCore [cdcr-target_shard1_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@70f8b86e
[junit4] 2> 2020097 INFO (coreCloseExecutor-8543-thread-1) [n:127.0.0.1:63903_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.CdcrRequestHandler Solr core is being closed - shutting down CDCR handler @ cdcr-target:shard1
[junit4] 2> 2020105 INFO (jetty-launcher-3196-thread-1) [ ] o.a.s.c.Overseer Overseer (id=97007824525393923-127.0.0.1:63903_solr-n_0000000000) closing
[junit4] 2> 2020105 INFO (OverseerStateUpdate-97007824525393923-127.0.0.1:63903_solr-n_0000000000) [n:127.0.0.1:63903_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:63903_solr
[junit4] 2> 2020106 INFO (zkCallback-3202-thread-5-processing-n:127.0.0.1:63903_solr) [n:127.0.0.1:63903_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/cdcr-target/state.json] for collection [cdcr-target] has occurred - updating... (live nodes size: [1])
[junit4] 2> 2021610 WARN (zkCallback-3202-thread-5-processing-n:127.0.0.1:63903_solr) [n:127.0.0.1:63903_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /collections/cdcr-target/state.json]
[junit4] 2> 2021610 INFO (jetty-launcher-3196-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@3d969870{/solr,null,UNAVAILABLE}
[junit4] 2> 2021615 INFO (TEST-CdcrBootstrapTest.testConvertClusterToCdcrAndBootstrap-seed#[8ECD054F4BAB207A]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:43498 43498
[junit4] 2> 2021639 INFO (Thread-5866) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:43498 43498
[junit4] 2> 2021640 WARN (Thread-5866) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/aliases.json
[junit4] 2> 3 /solr/clusterprops.json
[junit4] 2> 2 /solr/configs/cdcr-target/managed-schema
[junit4] 2> 2 /solr/collections/cdcr-target/leaders/shard1/leader
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/collections/cdcr-target/cdcr/state/process
[junit4] 2> 3 /solr/clusterstate.json
[junit4] 2> 2 /solr/collections/cdcr-target/cdcr/state/buffer
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 17 /solr/overseer/collection-queue-work
[junit4] 2> 5 /solr/overseer/queue
[junit4] 2> 3 /solr/live_nodes
[junit4] 2> 3 /solr/collections
[junit4] 2>
[junit4] 2> 2021641 INFO (TEST-CdcrBootstrapTest.testConvertClusterToCdcrAndBootstrap-seed#[8ECD054F4BAB207A]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testConvertClusterToCdcrAndBootstrap
[junit4] 2> 2021642 INFO (SUITE-CdcrBootstrapTest-seed#[8ECD054F4BAB207A]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J1/temp/solr.cloud.CdcrBootstrapTest_8ECD054F4BAB207A-001
[junit4] 2> Nov 27, 2016 4:45:52 AM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene62): {_version_=PostingsFormat(name=LuceneFixedGap), xyz=PostingsFormat(name=MockRandom), id=TestBloomFilteredLucenePostings(BloomFilteringPostingsFormat(Lucene50(blocksize=128)))}, docValues:{}, maxPointsInLeafNode=900, maxMBSortInHeap=5.949910311828333, sim=RandomSimilarity(queryNorm=true,coord=crazy): {}, locale=en-AU, timezone=Libya
[junit4] 2> NOTE: SunOS 5.11 amd64/Oracle Corporation 1.8.0_102 (64-bit)/cpus=3,threads=1,free=304128320,total=484970496
[junit4] 2> NOTE: All tests run in this JVM: [RuleEngineTest, RAMDirectoryFactoryTest, HdfsRecoveryZkTest, ClusterStateTest, TestCloudSchemaless, TestMaxScoreQueryParser, TestSchemaResource, AutoCommitTest, DateRangeFieldTest, BufferStoreTest, TestNumericTerms32, TestMacroExpander, ResourceLoaderTest, OverseerStatusTest, ShowFileRequestHandlerTest, TestSearchPerf, TestSolrConfigHandlerCloud, TestSolrCoreSnapshots, SimpleCollectionCreateDeleteTest, CoreAdminCreateDiscoverTest, JavabinLoaderTest, CollectionReloadTest, TestStressCloudBlindAtomicUpdates, TestConfigSetsAPIZkFailure, MinimalSchemaTest, SecurityConfHandlerTest, TestSuggestSpellingConverter, SpellCheckComponentTest, HighlighterConfigTest, TestCloudInspectUtil, TestCollapseQParserPlugin, TestBlobHandler, SuggestComponentContextFilterQueryTest, TestHdfsBackupRestoreCore, TestCustomSort, QueryParsingTest, SignatureUpdateProcessorFactoryTest, BigEndianAscendingWordDeserializerTest, TestScoreJoinQPNoScore, DistributedExpandComponentTest, HdfsChaosMonkeySafeLeaderTest, TestUnifiedSolrHighlighter, TestInitParams, TestSolrCoreProperties, BitVectorTest, TestBinaryResponseWriter, SortByFunctionTest, TestSubQueryTransformerCrossCore, TestUninvertingReader, TestDynamicFieldResource, TestRealTimeGet, DirectoryFactoryTest, TestLMJelinekMercerSimilarityFactory, BlockJoinFacetDistribTest, OpenCloseCoreStressTest, TestUseDocValuesAsStored, CurrencyFieldOpenExchangeTest, TestDownShardTolerantSearch, TestManagedSynonymFilterFactory, TestFieldCache, TestMiniSolrCloudCluster, LeaderInitiatedRecoveryOnShardRestartTest, DistanceFunctionTest, HdfsNNFailoverTest, HdfsTlogReplayBufferedWhileIndexingTest, TestUniqueKeyFieldResource, TestSolrXml, CdcrReplicationHandlerTest, SliceStateTest, ReturnFieldsTest, TestSolrCloudWithKerberosAlt, SolrCloudExampleTest, DeleteShardTest, TestRecovery, TestLeaderElectionZkExpiry, TestSimpleTrackingShardHandler, BasicDistributedZk2Test, CacheHeaderTest, BlockJoinFacetSimpleTest, SolrIndexSplitterTest, TestSizeLimitedDistributedMap, ShufflingReplicaListTransformerTest, CoreMergeIndexesAdminHandlerTest, PreAnalyzedFieldTest, CSVRequestHandlerTest, BasicFunctionalityTest, UpdateRequestProcessorFactoryTest, DistributedTermsComponentTest, IndexSchemaTest, TestHashQParserPlugin, SolrCoreCheckLockOnStartupTest, TestManagedSchemaThreadSafety, DistributedFacetPivotLargeTest, StatsReloadRaceTest, TestHdfsUpdateLog, TestPHPSerializedResponseWriter, CreateCollectionCleanupTest, TestDeleteCollectionOnDownNodes, TestRestManager, TestBadConfig, TestAuthenticationFramework, SolrCmdDistributorTest, BadIndexSchemaTest, TestJsonFacetRefinement, RollingRestartTest, TlogReplayBufferedWhileIndexingTest, JSONWriterTest, DeleteInactiveReplicaTest, ConvertedLegacyTest, TestSQLHandler, RequestHandlersTest, TestCustomStream, FieldMutatingUpdateProcessorTest, AddSchemaFieldsUpdateProcessorFactoryTest, TestUtils, TestRebalanceLeaders, TestLuceneMatchVersion, TestFastWriter, NoCacheHeaderTest, MBeansHandlerTest, ZkStateWriterTest, HdfsBasicDistributedZkTest, HLLUtilTest, FieldAnalysisRequestHandlerTest, ConfigSetsAPITest, TestQuerySenderNoQuery, AnalysisErrorHandlingTest, TestManagedSchema, SuggesterWFSTTest, TestReqParamsAPI, DistributedFacetPivotWhiteBoxTest, TestMinMaxOnMultiValuedField, CleanupOldIndexTest, TestReversedWildcardFilterFactory, TestRandomFlRTGCloud, WordBreakSolrSpellCheckerTest, TestSmileRequest, EchoParamsTest, ExternalFileFieldSortTest, TestDistributedStatsComponentCardinality, TestRequestForwarding, URLClassifyProcessorTest, SharedFSAutoReplicaFailoverTest, TestSchemaVersionResource, DistanceUnitsTest, TestFreeTextSuggestions, RankQueryTest, TestSystemIdResolver, HdfsDirectoryFactoryTest, TestFieldCacheWithThreads, SuggesterTSTTest, DefaultValueUpdateProcessorTest, VMParamsZkACLAndCredentialsProvidersTest, TestAddFieldRealTimeGet, CachingDirectoryFactoryTest, TestConfigSetImmutable, TestStressUserVersions, TestRangeQuery, HdfsWriteToMultipleCollectionsTest, TestDistributedGrouping, TestTestInjection, ChaosMonkeySafeLeaderTest, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest, OverseerTest, LeaderElectionIntegrationTest, BasicZkTest, FullSolrCloudDistribCmdsTest, TestReplicationHandler, TestRandomFaceting, TestZkChroot, TestRandomDVFaceting, ShardRoutingCustomTest, TestFaceting, TermVectorComponentDistributedTest, ZkControllerTest, TestStressReorder, TestJoin, HardAutoCommitTest, StatsComponentTest, HighlighterTest, DistributedQueryElevationComponentTest, TestCoreDiscovery, TestExtendedDismaxParser, SpellCheckCollatorTest, CoreAdminHandlerTest, DocValuesTest, SolrInfoMBeanTest, LukeRequestHandlerTest, TestWriterPerf, FileBasedSpellCheckerTest, TestValueSourceCache, TestIndexingPerformance, MoreLikeThisHandlerTest, FastVectorHighlighterTest, LoggingHandlerTest, JSONWriterTest, UniqFieldsUpdateProcessorFactoryTest, BinaryUpdateRequestHandlerTest, SearchHandlerTest, TestBinaryResponseWriter, TestLFUCache, TestLMDirichletSimilarityFactory, TestJmxMonitoredMap, PluginInfoTest, DateMathParserTest, DateFieldTest, DOMUtilTest, ZkNodePropsTest, FileUtilsTest, SolrTestCaseJ4Test, TestCrossCoreJoin, TestCursorMarkWithoutUniqueKey, TestDistributedMissingSort, TestTolerantSearch, TestEmbeddedSolrServerConstructors, TestJettySolrRunner, ConnectionReuseTest, ActionThrottleTest, AsyncCallRequestStatusResponseTest, CdcrBootstrapTest]
[junit4] Completed [479/658 (1!)] on J1 in 188.54s, 3 tests, 1 failure <<< FAILURES!
[...truncated 61383 lines...]
[JENKINS] Lucene-Solr-6.x-Solaris (64bit/jdk1.8.0) - Build # 518 -
Failure!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Solaris/518/
Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
2 tests failed.
FAILED: org.apache.solr.cloud.RecoveryZkTest.test
Error Message:
Error from server at https://127.0.0.1:35281/solr: Cannot create collection recoverytest. Value of maxShardsPerNode is 1, and the number of nodes currently live or live and part of your createNodeSet is 1. This allows a maximum of 1 to be created. Value of numShards is 1 and value of replicationFactor is 2. This requires 2 shards to be created (higher than the allowed number)
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at https://127.0.0.1:35281/solr: Cannot create collection recoverytest. Value of maxShardsPerNode is 1, and the number of nodes currently live or live and part of your createNodeSet is 1. This allows a maximum of 1 to be created. Value of numShards is 1 and value of replicationFactor is 2. This requires 2 shards to be created (higher than the allowed number)
at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:593)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:262)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:251)
at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:435)
at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:387)
at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:1340)
at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:1091)
at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:1033)
at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:149)
at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:166)
at org.apache.solr.cloud.RecoveryZkTest.test(RecoveryZkTest.java:68)
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:367)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:811)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:462)
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:367)
at java.lang.Thread.run(Thread.java:745)
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.hdfs.HdfsRecoveryZkTest
Error Message:
ObjectTracker found 1 object(s) that were not released!!! [HdfsTransactionLog] org.apache.solr.common.util.ObjectReleaseTracker$ObjectTrackerException at org.apache.solr.common.util.ObjectReleaseTracker.track(ObjectReleaseTracker.java:43) at org.apache.solr.update.HdfsTransactionLog.<init>(HdfsTransactionLog.java:130) at org.apache.solr.update.HdfsUpdateLog.init(HdfsUpdateLog.java:202) at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:137) at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:94) at org.apache.solr.update.DirectUpdateHandler2.<init>(DirectUpdateHandler2.java:102) at sun.reflect.GeneratedConstructorAccessor161.newInstance(Unknown Source) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:423) at org.apache.solr.core.SolrCore.createInstance(SolrCore.java:705) at org.apache.solr.core.SolrCore.createUpdateHandler(SolrCore.java:767) at org.apache.solr.core.SolrCore.initUpdateHandler(SolrCore.java:1006) at org.apache.solr.core.SolrCore.<init>(SolrCore.java:871) at org.apache.solr.core.SolrCore.<init>(SolrCore.java:775) at org.apache.solr.core.CoreContainer.create(CoreContainer.java:842) at org.apache.solr.core.CoreContainer.lambda$load$0(CoreContainer.java:498) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)
Stack Trace:
java.lang.AssertionError: ObjectTracker found 1 object(s) that were not released!!! [HdfsTransactionLog]
org.apache.solr.common.util.ObjectReleaseTracker$ObjectTrackerException
at org.apache.solr.common.util.ObjectReleaseTracker.track(ObjectReleaseTracker.java:43)
at org.apache.solr.update.HdfsTransactionLog.<init>(HdfsTransactionLog.java:130)
at org.apache.solr.update.HdfsUpdateLog.init(HdfsUpdateLog.java:202)
at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:137)
at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:94)
at org.apache.solr.update.DirectUpdateHandler2.<init>(DirectUpdateHandler2.java:102)
at sun.reflect.GeneratedConstructorAccessor161.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at org.apache.solr.core.SolrCore.createInstance(SolrCore.java:705)
at org.apache.solr.core.SolrCore.createUpdateHandler(SolrCore.java:767)
at org.apache.solr.core.SolrCore.initUpdateHandler(SolrCore.java:1006)
at org.apache.solr.core.SolrCore.<init>(SolrCore.java:871)
at org.apache.solr.core.SolrCore.<init>(SolrCore.java:775)
at org.apache.solr.core.CoreContainer.create(CoreContainer.java:842)
at org.apache.solr.core.CoreContainer.lambda$load$0(CoreContainer.java:498)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
at __randomizedtesting.SeedInfo.seed([8B11045FDE87FCC5]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.junit.Assert.assertNull(Assert.java:551)
at org.apache.solr.SolrTestCaseJ4.teardownTestCases(SolrTestCaseJ4.java:260)
at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
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$7.evaluate(RandomizedRunner.java:870)
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:367)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 11226 lines...]
[junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4] 2> Creating dataDir: /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_8B11045FDE87FCC5-001/init-core-data-001
[junit4] 2> 722886 INFO (SUITE-RecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, value=NaN, ssl=NaN, clientAuth=NaN)
[junit4] 2> 722887 INFO (SUITE-RecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_8B11045FDE87FCC5-001/tempDir-001
[junit4] 2> 722888 INFO (SUITE-RecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 722888 INFO (Thread-1242) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 722888 INFO (Thread-1242) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 722988 INFO (SUITE-RecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:34726
[junit4] 2> 723006 INFO (jetty-launcher-687-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 723008 INFO (jetty-launcher-687-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@7e50e879{/solr,null,AVAILABLE}
[junit4] 2> 723011 INFO (jetty-launcher-687-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@7d32a5dd{SSL,[ssl, http/1.1]}{127.0.0.1:59078}
[junit4] 2> 723011 INFO (jetty-launcher-687-thread-1) [ ] o.e.j.s.Server Started @725880ms
[junit4] 2> 723011 INFO (jetty-launcher-687-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=59078}
[junit4] 2> 723011 ERROR (jetty-launcher-687-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 723011 INFO (jetty-launcher-687-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 723011 INFO (jetty-launcher-687-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 723011 INFO (jetty-launcher-687-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 723011 INFO (jetty-launcher-687-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-11-27T14:27:44.190Z
[junit4] 2> 723015 INFO (jetty-launcher-687-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 723016 INFO (jetty-launcher-687-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@52241a60{/solr,null,AVAILABLE}
[junit4] 2> 723018 INFO (jetty-launcher-687-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@7bec9988{SSL,[ssl, http/1.1]}{127.0.0.1:35281}
[junit4] 2> 723018 INFO (jetty-launcher-687-thread-2) [ ] o.e.j.s.Server Started @725888ms
[junit4] 2> 723018 INFO (jetty-launcher-687-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=35281}
[junit4] 2> 723018 ERROR (jetty-launcher-687-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 723019 INFO (jetty-launcher-687-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 723019 INFO (jetty-launcher-687-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 723019 INFO (jetty-launcher-687-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 723019 INFO (jetty-launcher-687-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-11-27T14:27:44.198Z
[junit4] 2> 723028 INFO (jetty-launcher-687-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 723240 INFO (jetty-launcher-687-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 723252 INFO (jetty-launcher-687-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 723253 INFO (jetty-launcher-687-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34726/solr
[junit4] 2> 723286 INFO (jetty-launcher-687-thread-2) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 723286 INFO (jetty-launcher-687-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34726/solr
[junit4] 2> 723314 INFO (jetty-launcher-687-thread-1) [n:127.0.0.1:59078_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:59078_solr
[junit4] 2> 723317 INFO (jetty-launcher-687-thread-1) [n:127.0.0.1:59078_solr ] o.a.s.c.Overseer Overseer (id=97010113843757060-127.0.0.1:59078_solr-n_0000000000) starting
[junit4] 2> 723325 INFO (jetty-launcher-687-thread-1) [n:127.0.0.1:59078_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59078_solr
[junit4] 2> 723395 INFO (jetty-launcher-687-thread-1) [n:127.0.0.1:59078_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_8B11045FDE87FCC5-001/tempDir-001/node1/.
[junit4] 2> 723423 INFO (jetty-launcher-687-thread-2) [n:127.0.0.1:35281_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 723429 INFO (jetty-launcher-687-thread-2) [n:127.0.0.1:35281_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35281_solr
[junit4] 2> 723510 INFO (jetty-launcher-687-thread-2) [n:127.0.0.1:35281_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_8B11045FDE87FCC5-001/tempDir-001/node2/.
[junit4] 2> 723518 INFO (zkCallback-694-thread-1-processing-n:127.0.0.1:59078_solr) [n:127.0.0.1:59078_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 723528 INFO (SUITE-RecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 723529 INFO (SUITE-RecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:34726/solr ready
[junit4] 2> 723535 INFO (zkCallback-699-thread-1-processing-n:127.0.0.1:35281_solr) [n:127.0.0.1:35281_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 723550 INFO (TEST-RecoveryZkTest.test-seed#[8B11045FDE87FCC5]) [ ] o.a.s.SolrTestCaseJ4 ###Starting test
[junit4] 2> 723603 INFO (qtp1955414459-4683) [n:127.0.0.1:35281_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> 723610 INFO (OverseerThreadFactory-2129-thread-1-processing-n:127.0.0.1:59078_solr) [n:127.0.0.1:59078_solr ] o.a.s.c.CreateCollectionCmd Create collection recoverytest
[junit4] 2> 723610 WARN (OverseerThreadFactory-2129-thread-1-processing-n:127.0.0.1:59078_solr) [n:127.0.0.1:59078_solr ] o.a.s.c.CreateCollectionCmd Specified replicationFactor of 2 on collection recoverytest is higher than or equal to the number of Solr instances currently live or live and part of your createNodeSet(1). It's unusual to run two replica of the same slice on the same Solr-instance.
[junit4] 2> 723611 ERROR (OverseerThreadFactory-2129-thread-1-processing-n:127.0.0.1:59078_solr) [n:127.0.0.1:59078_solr ] o.a.s.c.OverseerCollectionMessageHandler Collection: recoverytest operation: create failed:org.apache.solr.common.SolrException: Cannot create collection recoverytest. Value of maxShardsPerNode is 1, and the number of nodes currently live or live and part of your createNodeSet is 1. This allows a maximum of 1 to be created. Value of numShards is 1 and value of replicationFactor is 2. This requires 2 shards to be created (higher than the allowed number)
[junit4] 2> at org.apache.solr.cloud.CreateCollectionCmd.call(CreateCollectionCmd.java:148)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionMessageHandler.processMessage(OverseerCollectionMessageHandler.java:224)
[junit4] 2> at org.apache.solr.cloud.OverseerTaskProcessor$Runner.run(OverseerTaskProcessor.java:463)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 723645 INFO (qtp1955414459-4683) [n:127.0.0.1:35281_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=400 QTime=41
[junit4] 2> 723648 INFO (TEST-RecoveryZkTest.test-seed#[8B11045FDE87FCC5]) [ ] o.a.s.SolrTestCaseJ4 ###Ending test
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest -Dtests.method=test -Dtests.seed=8B11045FDE87FCC5 -Dtests.slow=true -Dtests.locale=ar -Dtests.timezone=Atlantic/Madeira -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] ERROR 0.12s J0 | RecoveryZkTest.test <<<
[junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at https://127.0.0.1:35281/solr: Cannot create collection recoverytest. Value of maxShardsPerNode is 1, and the number of nodes currently live or live and part of your createNodeSet is 1. This allows a maximum of 1 to be created. Value of numShards is 1 and value of replicationFactor is 2. This requires 2 shards to be created (higher than the allowed number)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:593)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:262)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:251)
[junit4] > at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:435)
[junit4] > at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:387)
[junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:1340)
[junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:1091)
[junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:1033)
[junit4] > at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:149)
[junit4] > at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:166)
[junit4] > at org.apache.solr.cloud.RecoveryZkTest.test(RecoveryZkTest.java:68)
[junit4] > at java.lang.Thread.run(Thread.java:745)Throwable #2: java.lang.NullPointerException
[junit4] > at org.apache.solr.cloud.RecoveryZkTest.stopThreads(RecoveryZkTest.java:55)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 723658 INFO (jetty-launcher-687-thread-2) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@7d32a5dd{SSL,[ssl, http/1.1]}{127.0.0.1:0}
[junit4] 2> 723658 INFO (jetty-launcher-687-thread-2) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=101617813
[junit4] 2> 723662 INFO (jetty-launcher-687-thread-2) [ ] o.a.s.c.Overseer Overseer (id=97010113843757060-127.0.0.1:59078_solr-n_0000000000) closing
[junit4] 2> 723663 INFO (jetty-launcher-687-thread-1) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@7bec9988{SSL,[ssl, http/1.1]}{127.0.0.1:0}
[junit4] 2> 723664 INFO (jetty-launcher-687-thread-1) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=674466636
[junit4] 2> 723672 INFO (jetty-launcher-687-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@52241a60{/solr,null,UNAVAILABLE}
[junit4] 2> 725183 WARN (zkCallback-694-thread-2-processing-n:127.0.0.1:59078_solr) [n:127.0.0.1:59078_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 725184 WARN (OverseerStateUpdate-97010113843757060-127.0.0.1:59078_solr-n_0000000000) [n:127.0.0.1:59078_solr ] o.a.s.c.Overseer Solr cannot talk to ZK, exiting Overseer work queue loop
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /live_nodes
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1472)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:339)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:336)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:60)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:336)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.refreshLiveNodes(ZkStateReader.java:664)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.updateClusterState(ZkStateReader.java:268)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:140)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 725184 INFO (OverseerStateUpdate-97010113843757060-127.0.0.1:59078_solr-n_0000000000) [n:127.0.0.1:59078_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:59078_solr
[junit4] 2> 725184 INFO (zkCallback-694-thread-1-processing-n:127.0.0.1:59078_solr) [n:127.0.0.1:59078_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 725185 INFO (jetty-launcher-687-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@7e50e879{/solr,null,UNAVAILABLE}
[junit4] 2> 725194 INFO (SUITE-RecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:34726 34726
[junit4] 2> 725219 INFO (Thread-1242) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:34726 34726
[junit4] 2> 725220 WARN (Thread-1242) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/aliases.json
[junit4] 2> 2 /solr/security.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/clusterstate.json
[junit4] 2> 3 /solr/clusterprops.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/live_nodes
[junit4] 2> 3 /solr/collections
[junit4] 2>
[junit4] 2> 725221 INFO (SUITE-RecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.RecoveryZkTest_8B11045FDE87FCC5-001
[junit4] 2> Nov 27, 2016 2:27:46 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene62): {}, docValues:{}, maxPointsInLeafNode=455, maxMBSortInHeap=7.682942685719383, sim=RandomSimilarity(queryNorm=false,coord=crazy): {}, locale=ar, timezone=Atlantic/Madeira
[junit4] 2> NOTE: SunOS 5.11 amd64/Oracle Corporation 1.8.0_102 (64-bit)/cpus=3,threads=1,free=86406184,total=261984256
[junit4] 2> NOTE: All tests run in this JVM: [TestPKIAuthenticationPlugin, TestDocumentBuilder, ResponseHeaderTest, TestShardHandlerFactory, TestOrdValues, TestSolrConfigHandlerConcurrent, IndexBasedSpellCheckerTest, TestRandomRequestDistribution, TestManagedSchemaAPI, TestSolrCloudSnapshots, TestConfigReload, TestFieldCacheVsDocValues, HdfsUnloadDistributedZkTest, TestPhraseSuggestions, VersionInfoTest, ShardRoutingTest, TestHashPartitioner, TestCustomDocTransformer, HighlighterTest, CollectionsAPIAsyncDistributedZkTest, TestUpdate, TestComplexPhraseQParserPlugin, TestTrackingShardHandlerFactory, HardAutoCommitTest, RestartWhileUpdatingTest, TestUseDocValuesAsStored2, TestStressReorder, TestComponentsName, TestConfigOverlay, HdfsCollectionsAPIDistributedZkTest, CdcrUpdateLogTest, TestSchemaNameResource, SolrCoreTest, SampleTest, TestLeaderElectionWithEmptyReplica, HttpPartitionTest, TestCryptoKeys, TestDistributedSearch, DistribDocExpirationUpdateProcessorTest, PrimitiveFieldTypeTest, TestSolrIndexConfig, CurrencyFieldXmlFileTest, SpatialHeatmapFacetsTest, TestLeaderInitiatedRecoveryThread, ReplicaListTransformerTest, TestStressRecovery, TestOverriddenPrefixQueryForCustomFieldType, ResponseLogComponentTest, BJQParserTest, TestXmlQParserPlugin, RecoveryZkTest]
[junit4] Completed [170/658 (1!)] on J0 in 3.25s, 1 test, 1 error <<< FAILURES!
[...truncated 1096 lines...]
[junit4] Suite: org.apache.solr.cloud.hdfs.HdfsRecoveryZkTest
[junit4] 2> Creating dataDir: /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_8B11045FDE87FCC5-001/init-core-data-001
[junit4] 2> 2423136 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, value=NaN, ssl=NaN, clientAuth=NaN)
[junit4] 2> 2423137 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_8B11045FDE87FCC5-001/tempDir-001
[junit4] 2> 2423137 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 2423137 INFO (Thread-6255) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 2423137 INFO (Thread-6255) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 2423237 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:33037
[junit4] 2> 2423250 INFO (jetty-launcher-10861-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 2423252 INFO (jetty-launcher-10861-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@3a606bd4{/solr,null,AVAILABLE}
[junit4] 2> 2423250 INFO (jetty-launcher-10861-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 2423257 INFO (jetty-launcher-10861-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@17aa2228{/solr,null,AVAILABLE}
[junit4] 2> 2423257 INFO (jetty-launcher-10861-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@11094a56{SSL,[ssl, http/1.1]}{127.0.0.1:46673}
[junit4] 2> 2423257 INFO (jetty-launcher-10861-thread-1) [ ] o.e.j.s.Server Started @2426868ms
[junit4] 2> 2423257 INFO (jetty-launcher-10861-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=46673}
[junit4] 2> 2423257 ERROR (jetty-launcher-10861-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 2423257 INFO (jetty-launcher-10861-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 2423257 INFO (jetty-launcher-10861-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 2423258 INFO (jetty-launcher-10861-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 2423258 INFO (jetty-launcher-10861-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-11-27T14:56:04.437Z
[junit4] 2> 2423258 INFO (jetty-launcher-10861-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@46ea1f5c{SSL,[ssl, http/1.1]}{127.0.0.1:48362}
[junit4] 2> 2423258 INFO (jetty-launcher-10861-thread-2) [ ] o.e.j.s.Server Started @2426870ms
[junit4] 2> 2423258 INFO (jetty-launcher-10861-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=48362}
[junit4] 2> 2423258 ERROR (jetty-launcher-10861-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 2423259 INFO (jetty-launcher-10861-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 2423259 INFO (jetty-launcher-10861-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 2423259 INFO (jetty-launcher-10861-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 2423259 INFO (jetty-launcher-10861-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-11-27T14:56:04.438Z
[junit4] 2> 2423262 INFO (jetty-launcher-10861-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 2423262 INFO (jetty-launcher-10861-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 2423270 INFO (jetty-launcher-10861-thread-2) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 2423270 INFO (jetty-launcher-10861-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:33037/solr
[junit4] 2> 2423271 INFO (jetty-launcher-10861-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 2423272 INFO (jetty-launcher-10861-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:33037/solr
[junit4] 2> 2423307 INFO (jetty-launcher-10861-thread-1) [n:127.0.0.1:46673_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:46673_solr
[junit4] 2> 2423308 INFO (jetty-launcher-10861-thread-2) [n:127.0.0.1:48362_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48362_solr
[junit4] 2> 2423310 INFO (jetty-launcher-10861-thread-1) [n:127.0.0.1:46673_solr ] o.a.s.c.Overseer Overseer (id=97010225271144454-127.0.0.1:46673_solr-n_0000000000) starting
[junit4] 2> 2423323 INFO (jetty-launcher-10861-thread-1) [n:127.0.0.1:46673_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46673_solr
[junit4] 2> 2423380 INFO (zkCallback-10871-thread-1-processing-n:127.0.0.1:48362_solr) [n:127.0.0.1:48362_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 2423394 INFO (zkCallback-10872-thread-1-processing-n:127.0.0.1:46673_solr) [n:127.0.0.1:46673_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 2423445 INFO (zkCallback-10871-thread-1-processing-n:127.0.0.1:48362_solr) [n:127.0.0.1:48362_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 2423489 INFO (OverseerStateUpdate-97010225271144454-127.0.0.1:46673_solr-n_0000000000) [n:127.0.0.1:46673_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 2423515 INFO (jetty-launcher-10861-thread-1) [n:127.0.0.1:46673_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_8B11045FDE87FCC5-001/tempDir-001/node1/.
[junit4] 2> 2423593 INFO (jetty-launcher-10861-thread-2) [n:127.0.0.1:48362_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_8B11045FDE87FCC5-001/tempDir-001/node2/.
[junit4] 2> 2423601 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 2423603 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:33037/solr ready
[junit4] 1> Formatting using clusterid: testClusterID
[junit4] 2> 2423640 WARN (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.h.m.i.MetricsConfig Cannot locate configuration: tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
[junit4] 2> 2423649 WARN (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 2423651 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 2423665 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.m.log Extract jar:file:/export/home/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.2-tests.jar!/webapps/hdfs to ./temp/Jetty_solaris.vm_46060_hdfs____zb6w1m/webapp
[junit4] 2> 2424216 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@solaris-vm:46060
[junit4] 2> 2424345 WARN (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 2424346 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 2424360 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.m.log Extract jar:file:/export/home/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.2-tests.jar!/webapps/datanode to ./temp/Jetty_localhost_41896_datanode____src61r/webapp
[junit4] 2> 2424820 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:41896
[junit4] 2> 2424895 WARN (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 2424896 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 2424912 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.m.log Extract jar:file:/export/home/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.2-tests.jar!/webapps/datanode to ./temp/Jetty_localhost_64880_datanode____emwjo9/webapp
[junit4] 2> 2424957 INFO (IPC Server handler 2 on 52615) [ ] BlockStateChange BLOCK* processReport: from storage DS-38811a91-dbc5-4f0e-9d5f-96d3c1408fcb node DatanodeRegistration(127.0.0.1:58758, datanodeUuid=0e41dbbf-963c-4d5a-89e1-a407734c9ee9, infoPort=62601, infoSecurePort=0, ipcPort=36459, storageInfo=lv=-56;cid=testClusterID;nsid=1862498236;c=0), blocks: 0, hasStaleStorage: true, processing time: 0 msecs
[junit4] 2> 2424957 INFO (IPC Server handler 2 on 52615) [ ] BlockStateChange BLOCK* processReport: from storage DS-31a6424c-08ad-4f03-8663-73d81dac5516 node DatanodeRegistration(127.0.0.1:58758, datanodeUuid=0e41dbbf-963c-4d5a-89e1-a407734c9ee9, infoPort=62601, infoSecurePort=0, ipcPort=36459, storageInfo=lv=-56;cid=testClusterID;nsid=1862498236;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
[junit4] 2> 2425453 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:64880
[junit4] 2> 2426030 INFO (IPC Server handler 5 on 52615) [ ] BlockStateChange BLOCK* processReport: from storage DS-165617a1-5bfd-453b-9219-8edf920eacd9 node DatanodeRegistration(127.0.0.1:38289, datanodeUuid=c71bb449-fb2e-4319-96f7-fa7381210cd9, infoPort=43425, infoSecurePort=0, ipcPort=59954, storageInfo=lv=-56;cid=testClusterID;nsid=1862498236;c=0), blocks: 0, hasStaleStorage: true, processing time: 0 msecs
[junit4] 2> 2426030 INFO (IPC Server handler 5 on 52615) [ ] BlockStateChange BLOCK* processReport: from storage DS-20d5653e-c31a-4421-acca-7ef2c5693694 node DatanodeRegistration(127.0.0.1:38289, datanodeUuid=c71bb449-fb2e-4319-96f7-fa7381210cd9, infoPort=43425, infoSecurePort=0, ipcPort=59954, storageInfo=lv=-56;cid=testClusterID;nsid=1862498236;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
[junit4] 2> 2426170 INFO (TEST-HdfsRecoveryZkTest.test-seed#[8B11045FDE87FCC5]) [ ] o.a.s.SolrTestCaseJ4 ###Starting test
[junit4] 2> 2426215 INFO (qtp2127796789-48839) [n:127.0.0.1:46673_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> 2426219 INFO (OverseerThreadFactory-9711-thread-1-processing-n:127.0.0.1:46673_solr) [n:127.0.0.1:46673_solr ] o.a.s.c.CreateCollectionCmd Create collection recoverytest
[junit4] 2> 2426344 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_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> 2426359 INFO (qtp634849440-48850) [n:127.0.0.1:48362_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> 2426466 INFO (zkCallback-10871-thread-1-processing-n:127.0.0.1:48362_solr) [n:127.0.0.1:48362_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> 2426466 INFO (zkCallback-10872-thread-1-processing-n:127.0.0.1:46673_solr) [n:127.0.0.1:46673_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> 2427357 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 2427366 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.s.IndexSchema [recoverytest_shard1_replica1] Schema name=minimal
[junit4] 2> 2427369 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_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> 2427370 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.CoreContainer Creating SolrCore 'recoverytest_shard1_replica1' using configuration from collection recoverytest
[junit4] 2> 2427370 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 2427377 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://solaris-vm:52615/data
[junit4] 2> 2427377 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
[junit4] 2> 2427377 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.SolrCore [[recoverytest_shard1_replica1] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_8B11045FDE87FCC5-001/tempDir-001/node1/recoverytest_shard1_replica1], dataDir=[hdfs://solaris-vm:52615/data/recoverytest/core_node1/data/]
[junit4] 2> 2427377 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://solaris-vm:52615/data/recoverytest/core_node1/data/snapshot_metadata
[junit4] 2> 2427379 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.s.IndexSchema [recoverytest_shard1_replica2] Schema name=minimal
[junit4] 2> 2427381 INFO (qtp634849440-48850) [n:127.0.0.1:48362_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> 2427382 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.CoreContainer Creating SolrCore 'recoverytest_shard1_replica2' using configuration from collection recoverytest
[junit4] 2> 2427383 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://solaris-vm:52615/data
[junit4] 2> 2427383 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
[junit4] 2> 2427383 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.c.SolrCore [[recoverytest_shard1_replica2] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_8B11045FDE87FCC5-001/tempDir-001/node2/recoverytest_shard1_replica2], dataDir=[hdfs://solaris-vm:52615/data/recoverytest/core_node2/data/]
[junit4] 2> 2427383 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://solaris-vm:52615/data/recoverytest/core_node2/data/snapshot_metadata
[junit4] 2> 2427386 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 2427387 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
[junit4] 2> 2427387 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Creating new global HDFS BlockCache
[junit4] 2> 2427390 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 2427390 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
[junit4] 2> 2427398 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 2427399 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 2427400 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://solaris-vm:52615/data/recoverytest/core_node1/data
[junit4] 2> 2427400 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://solaris-vm:52615/data/recoverytest/core_node2/data
[junit4] 2> 2427421 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://solaris-vm:52615/data/recoverytest/core_node1/data/index
[junit4] 2> 2427429 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 2427429 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
[junit4] 2> 2427434 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 2427437 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://solaris-vm:52615/data/recoverytest/core_node2/data/index
[junit4] 2> 2427446 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 2427446 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
[junit4] 2> 2427453 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 2427462 INFO (IPC Server handler 8 on 52615) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:58758 is added to blk_1073741825_1001{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-165617a1-5bfd-453b-9219-8edf920eacd9:NORMAL:127.0.0.1:38289|RBW], ReplicaUC[[DISK]DS-38811a91-dbc5-4f0e-9d5f-96d3c1408fcb:NORMAL:127.0.0.1:58758|RBW]]} size 0
[junit4] 2> 2427465 INFO (IPC Server handler 6 on 52615) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38289 is added to blk_1073741825_1001 size 71
[junit4] 2> 2427484 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.HdfsUpdateLog
[junit4] 2> 2427484 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2427484 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=3
[junit4] 2> 2427489 INFO (IPC Server handler 8 on 52615) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:58758 is added to blk_1073741826_1002{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-165617a1-5bfd-453b-9219-8edf920eacd9:NORMAL:127.0.0.1:38289|RBW], ReplicaUC[[DISK]DS-31a6424c-08ad-4f03-8663-73d81dac5516:NORMAL:127.0.0.1:58758|RBW]]} size 0
[junit4] 2> 2427491 INFO (IPC Server handler 4 on 52615) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38289 is added to blk_1073741826_1002 size 71
[junit4] 2> 2428071 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 2428071 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2428077 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.HdfsUpdateLog
[junit4] 2> 2428077 INFO (qtp634849440-48850) [n:127.0.0.1:48362_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> 2428077 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=3
[junit4] 2> 2428090 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@7a0b78f[recoverytest_shard1_replica1] main]
[junit4] 2> 2428091 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 2428091 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2428092 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 2428093 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 2428093 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 2428093 INFO (searcherExecutor-9716-thread-1-processing-n:127.0.0.1:46673_solr x:recoverytest_shard1_replica1 s:shard1 c:recoverytest r:core_node1) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.SolrCore [recoverytest_shard1_replica1] Registered new searcher Searcher@7a0b78f[recoverytest_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2428094 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1552163609534005248
[junit4] 2> 2428105 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 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> 2428107 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.s.SolrIndexSearcher Opening [Searcher@10c338bd[recoverytest_shard1_replica2] main]
[junit4] 2> 2428109 INFO (qtp634849440-48850) [n:127.0.0.1:48362_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> 2428109 INFO (qtp634849440-48850) [n:127.0.0.1:48362_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> 2428109 INFO (qtp634849440-48850) [n:127.0.0.1:48362_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> 2428109 INFO (qtp634849440-48850) [n:127.0.0.1:48362_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 1552163609549733888
[junit4] 2> 2428113 INFO (searcherExecutor-9717-thread-1-processing-n:127.0.0.1:48362_solr x:recoverytest_shard1_replica2 s:shard1 c:recoverytest r:core_node2) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 x:recoverytest_shard1_replica2] o.a.s.c.SolrCore [recoverytest_shard1_replica2] Registered new searcher Searcher@10c338bd[recoverytest_shard1_replica2] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2428116 INFO (zkCallback-10872-thread-3-processing-n:127.0.0.1:46673_solr) [n:127.0.0.1:46673_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> 2428116 INFO (zkCallback-10871-thread-1-processing-n:127.0.0.1:48362_solr) [n:127.0.0.1:48362_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> 2428611 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 2428611 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 2428611 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/
[junit4] 2> 2428612 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.u.PeerSync PeerSync: core=recoverytest_shard1_replica1 url=https://127.0.0.1:46673/solr START replicas=[https://127.0.0.1:48362/solr/recoverytest_shard1_replica2/] nUpdates=100
[junit4] 2> 2428612 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.u.PeerSync PeerSync: core=recoverytest_shard1_replica1 url=https://127.0.0.1:46673/solr DONE. We have no versions. sync failed.
[junit4] 2> 2428626 INFO (qtp634849440-48851) [n:127.0.0.1:48362_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=1
[junit4] 2> 2428628 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 2428628 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 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> 2428634 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/ shard1
[junit4] 2> 2428739 INFO (zkCallback-10872-thread-3-processing-n:127.0.0.1:46673_solr) [n:127.0.0.1:46673_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> 2428739 INFO (zkCallback-10871-thread-1-processing-n:127.0.0.1:48362_solr) [n:127.0.0.1:48362_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> 2428786 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 x:recoverytest_shard1_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 2428805 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_solr c:recoverytest s:shard1 r:core_node1 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=2462
[junit4] 2> 2428909 INFO (zkCallback-10871-thread-1-processing-n:127.0.0.1:48362_solr) [n:127.0.0.1:48362_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> 2428910 INFO (zkCallback-10872-thread-3-processing-n:127.0.0.1:46673_solr) [n:127.0.0.1:46673_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> 2429119 INFO (qtp634849440-48850) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_node2 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=2760
[junit4] 2> 2429122 INFO (qtp2127796789-48839) [n:127.0.0.1:46673_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> 2429227 INFO (zkCallback-10872-thread-2-processing-n:127.0.0.1:46673_solr) [n:127.0.0.1:46673_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> 2429227 INFO (zkCallback-10871-thread-1-processing-n:127.0.0.1:48362_solr) [n:127.0.0.1:48362_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> 2430123 INFO (qtp2127796789-48839) [n:127.0.0.1:46673_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=3909
[junit4] 2> 2430126 INFO (TEST-HdfsRecoveryZkTest.test-seed#[8B11045FDE87FCC5]) [ ] o.a.s.c.RecoveryZkTest Indexing 700 documents
[junit4] 2> 2430174 INFO (qtp634849440-48848) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-0 (1552163611680440320)]} 0 18
[junit4] 2> 2430175 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_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 (1552163611680440320)]} 0 34
[junit4] 2> 2430176 INFO (qtp634849440-48847) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-0 (1552163611673100288)]} 0 11
[junit4] 2> 2430177 INFO (qtp2127796789-48840) [n:127.0.0.1:46673_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 (1552163611673100288)]} 0 44
[junit4] 2> 2430182 INFO (qtp634849440-48846) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-1 (1552163611719237632)]} 0 2
[junit4] 2> 2430182 INFO (qtp634849440-48851) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-1 (1552163611719237633)]} 0 2
[junit4] 2> 2430182 INFO (qtp2127796789-48839) [n:127.0.0.1:46673_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 (1552163611719237632)]} 0 4
[junit4] 2> 2430183 INFO (qtp2127796789-48836) [n:127.0.0.1:46673_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 (1552163611719237633)]} 0 4
[junit4] 2> 2430190 INFO (qtp634849440-48853) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-2 (1552163611727626240)]} 0 1
[junit4] 2> 2430190 INFO (qtp634849440-48850) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-2 (1552163611728674816)]} 0 1
[junit4] 2> 2430190 INFO (qtp2127796789-48841) [n:127.0.0.1:46673_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 (1552163611728674816)]} 0 3
[junit4] 2> 2430190 INFO (qtp2127796789-48837) [n:127.0.0.1:46673_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 (1552163611727626240)]} 0 3
[junit4] 2> 2430195 INFO (qtp634849440-48852) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-3 (1552163611733917696)]} 0 0
[junit4] 2> 2430195 INFO (qtp634849440-48848) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-3 (1552163611733917697)]} 0 0
[junit4] 2> 2430195 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_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 (1552163611733917697)]} 0 2
[junit4] 2> 2430195 INFO (qtp2127796789-48843) [n:127.0.0.1:46673_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 (1552163611733917696)]} 0 2
[junit4] 2> 2430200 INFO (qtp634849440-48846) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[1-1 (-1552163611739160577)]} 0 0
[junit4] 2> 2430200 INFO (qtp634849440-48847) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[2-1 (-1552163611739160576)]} 0 1
[junit4] 2> 2430200 INFO (qtp2127796789-48839) [n:127.0.0.1:46673_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-1 (-1552163611739160577)]} 0 3
[junit4] 2> 2430200 INFO (qtp2127796789-48840) [n:127.0.0.1:46673_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-1 (-1552163611739160576)]} 0 3
[junit4] 2> 2430205 INFO (qtp634849440-48853) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-4 (1552163611744403457)]} 0 0
[junit4] 2> 2430205 INFO (qtp634849440-48851) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-4 (1552163611744403456)]} 0 1
[junit4] 2> 2430205 INFO (qtp2127796789-48841) [n:127.0.0.1:46673_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 (1552163611744403457)]} 0 3
[junit4] 2> 2430206 INFO (qtp2127796789-48836) [n:127.0.0.1:46673_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 (1552163611744403456)]} 0 3
[junit4] 2> 2430212 INFO (qtp634849440-48852) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[2-2 (-1552163611750694913)]} 0 1
[junit4] 2> 2430212 INFO (qtp634849440-48850) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[1-2 (-1552163611750694912)]} 0 1
[junit4] 2> 2430212 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_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-2 (-1552163611750694913)]} 0 3
[junit4] 2> 2430212 INFO (qtp2127796789-48837) [n:127.0.0.1:46673_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-2 (-1552163611750694912)]} 0 3
[junit4] 2> 2430218 INFO (qtp634849440-48848) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-5 (1552163611758034944)]} 0 1
[junit4] 2> 2430218 INFO (qtp634849440-48846) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-5 (1552163611758034945)]} 0 1
[junit4] 2> 2430218 INFO (qtp2127796789-48839) [n:127.0.0.1:46673_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 (1552163611758034945)]} 0 3
[junit4] 2> 2430218 INFO (qtp2127796789-48843) [n:127.0.0.1:46673_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 (1552163611758034944)]} 0 3
[junit4] 2> 2430225 INFO (qtp634849440-48847) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-6 (1552163611764326400)]} 0 1
[junit4] 2> 2430225 INFO (qtp634849440-48853) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-6 (1552163611764326401)]} 0 1
[junit4] 2> 2430225 INFO (qtp2127796789-48841) [n:127.0.0.1:46673_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 (1552163611764326401)]} 0 3
[junit4] 2> 2430225 INFO (qtp2127796789-48840) [n:127.0.0.1:46673_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 (1552163611764326400)]} 0 4
[junit4] 2> 2430226 INFO (OverseerCollectionConfigSetProcessor-97010225271144454-127.0.0.1:46673_solr-n_0000000000) [n:127.0.0.1:46673_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> 2430231 INFO (qtp634849440-48851) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[1-4 (-1552163611770617856)]} 0 1
[junit4] 2> 2430231 INFO (qtp634849440-48852) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[2-4 (-1552163611771666432)]} 0 1
[junit4] 2> 2430232 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_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-4 (-1552163611771666432)]} 0 3
[junit4] 2> 2430232 INFO (qtp2127796789-48836) [n:127.0.0.1:46673_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-4 (-1552163611770617856)]} 0 4
[junit4] 2> 2430236 INFO (qtp634849440-48850) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-7 (1552163611777957888)]} 0 1
[junit4] 2> 2430237 INFO (qtp634849440-48848) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-7 (1552163611777957889)]} 0 1
[junit4] 2> 2430237 INFO (qtp2127796789-48837) [n:127.0.0.1:46673_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 (1552163611777957888)]} 0 3
[junit4] 2> 2430237 INFO (qtp2127796789-48839) [n:127.0.0.1:46673_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 (1552163611777957889)]} 0 3
[junit4] 2> 2430246 INFO (qtp634849440-48846) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-8 (1552163611787395073)]} 0 0
[junit4] 2> 2430246 INFO (qtp634849440-48847) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-8 (1552163611787395072)]} 0 0
[junit4] 2> 2430246 INFO (qtp2127796789-48843) [n:127.0.0.1:46673_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 (1552163611787395072)]} 0 3
[junit4] 2> 2430246 INFO (qtp2127796789-48841) [n:127.0.0.1:46673_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 (1552163611787395073)]} 0 3
[junit4] 2> 2430255 INFO (qtp634849440-48851) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[2-8 (-1552163611794735104)]} 0 1
[junit4] 2> 2430256 INFO (qtp634849440-48853) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[1-8 (-1552163611795783680)]} 0 3
[junit4] 2> 2430256 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_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 (-1552163611795783680)]} 0 5
[junit4] 2> 2430257 INFO (qtp2127796789-48840) [n:127.0.0.1:46673_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 (-1552163611794735104)]} 0 6
[junit4] 2> 2430261 INFO (qtp634849440-48852) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-9 (1552163611803123712)]} 0 1
[junit4] 2> 2430261 INFO (qtp2127796789-48836) [n:127.0.0.1:46673_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 (1552163611803123712)]} 0 3
[junit4] 2> 2430262 INFO (qtp634849440-48850) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-9 (1552163611804172288)]} 0 1
[junit4] 2> 2430262 INFO (qtp2127796789-48837) [n:127.0.0.1:46673_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 (1552163611804172288)]} 0 3
[junit4] 2> 2430267 INFO (qtp634849440-48848) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-10 (1552163611809415168)]} 0 0
[junit4] 2> 2430267 INFO (qtp634849440-48846) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-10 (1552163611809415169)]} 0 1
[junit4] 2> 2430267 INFO (qtp2127796789-48839) [n:127.0.0.1:46673_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 (1552163611809415168)]} 0 3
[junit4] 2> 2430267 INFO (qtp2127796789-48843) [n:127.0.0.1:46673_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 (1552163611809415169)]} 0 3
[junit4] 2> 2430273 INFO (qtp634849440-48851) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[1-11 (1552163611815706624)]} 0 0
[junit4] 2> 2430273 INFO (qtp634849440-48847) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{add=[2-11 (1552163611815706625)]} 0 1
[junit4] 2> 2430273 INFO (qtp2127796789-48842) [n:127.0.0.1:46673_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 (1552163611815706625)]} 0 3
[junit4] 2> 2430273 INFO (qtp2127796789-48841) [n:127.0.0.1:46673_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 (1552163611815706624)]} 0 3
[junit4] 2> 2430278 INFO (qtp634849440-48853) [n:127.0.0.1:48362_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=https://127.0.0.1:46673/solr/recoverytest_shard1_replica1/&wt=javabin&version=2}{delete=[1-11 (-1552163611821998081)]} 0 0
[junit4] 2> 2430279 INFO (qtp634849440-48852) [n:127.0.0.1:48362_solr c:recoverytest s:shard1 r:core_
[...truncated too long message...]
ckmanagement.BlocksMap.size(BlocksMap.java:203)
[junit4] 2> at org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.getTotalBlocks(BlockManager.java:3370)
[junit4] 2> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getBlocksTotal(FSNamesystem.java:5729)
[junit4] 2> ... 54 more
[junit4] 2> 2442458 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:33037 33037
[junit4] 2> 2442459 INFO (SUITE-HdfsRecoveryZkTest-seed#[8B11045FDE87FCC5]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: test params are: codec=Lucene62, sim=RandomSimilarity(queryNorm=false,coord=yes): {}, locale=zh-SG, timezone=Australia/NSW
[junit4] 2> NOTE: SunOS 5.11 amd64/Oracle Corporation 1.8.0_102 (64-bit)/cpus=3,threads=2,free=302813440,total=518979584
[junit4] 2> NOTE: All tests run in this JVM: [TestPKIAuthenticationPlugin, TestDocumentBuilder, ResponseHeaderTest, TestShardHandlerFactory, TestOrdValues, TestSolrConfigHandlerConcurrent, IndexBasedSpellCheckerTest, TestRandomRequestDistribution, TestManagedSchemaAPI, TestSolrCloudSnapshots, TestConfigReload, TestFieldCacheVsDocValues, HdfsUnloadDistributedZkTest, TestPhraseSuggestions, VersionInfoTest, ShardRoutingTest, TestHashPartitioner, TestCustomDocTransformer, HighlighterTest, CollectionsAPIAsyncDistributedZkTest, TestUpdate, TestComplexPhraseQParserPlugin, TestTrackingShardHandlerFactory, HardAutoCommitTest, RestartWhileUpdatingTest, TestUseDocValuesAsStored2, TestStressReorder, TestComponentsName, TestConfigOverlay, HdfsCollectionsAPIDistributedZkTest, CdcrUpdateLogTest, TestSchemaNameResource, SolrCoreTest, SampleTest, TestLeaderElectionWithEmptyReplica, HttpPartitionTest, TestCryptoKeys, TestDistributedSearch, DistribDocExpirationUpdateProcessorTest, PrimitiveFieldTypeTest, TestSolrIndexConfig, CurrencyFieldXmlFileTest, SpatialHeatmapFacetsTest, TestLeaderInitiatedRecoveryThread, ReplicaListTransformerTest, TestStressRecovery, TestOverriddenPrefixQueryForCustomFieldType, ResponseLogComponentTest, BJQParserTest, TestXmlQParserPlugin, RecoveryZkTest, TestTolerantUpdateProcessorRandomCloud, DisMaxRequestHandlerTest, ConcurrentDeleteAndCreateCollectionTest, TestStressLiveNodes, SolrTestCaseJ4Test, RulesTest, TestNamedUpdateProcessors, DirectSolrConnectionTest, TestPseudoReturnFields, TestExclusionRuleCollectionAccess, SuggestComponentTest, SegmentsInfoRequestHandlerTest, TestJettySolrRunner, TestExactSharedStatsCache, CoreSorterTest, InfoHandlerTest, ZkNodePropsTest, TestInfoStreamLogging, TimeZoneUtilsTest, XsltUpdateRequestHandlerTest, TestInitQParser, FastVectorHighlighterTest, TestScoreJoinQPScore, ShardSplitTest, CdcrRequestHandlerTest, HdfsRestartWhileUpdatingTest, TestMissingGroups, TestPartialUpdateDeduplication, TestRemoteStreaming, NumericFieldsTest, TestTrieFacet, HdfsThreadLeakTest, OutputWriterTest, MergeStrategyTest, TestAnalyzedSuggestions, AlternateDirectoryTest, HdfsDirectoryTest, TestBinaryResponseWriter, DOMUtilTest, TestCloudDeleteByQuery, AssignTest, SolrRequestParserTest, BadComponentTest, TestDocTermOrds, DistributedFacetExistsSmallTest, PeerSyncTest, ZkStateReaderTest, XmlUpdateRequestHandlerTest, DistributedSuggestComponentTest, TestCollectionAPI, AnalyticsQueryTest, TestSerializedLuceneMatchVersion, FileUtilsTest, TermsComponentTest, SynonymTokenizerTest, TestCursorMarkWithoutUniqueKey, ZkCLITest, SOLR749Test, SharedFSAutoReplicaFailoverUtilsTest, DeleteStatusTest, TestReplicaProperties, DistributedFacetPivotLongTailTest, LeaderFailoverAfterPartitionTest, TestFieldTypeCollectionResource, TestCloudPivotFacet, TestSlowCompositeReaderWrapper, TestCharFilters, TestRTGBase, StatelessScriptUpdateProcessorFactoryTest, DistributedQueueTest, SolrPluginUtilsTest, TestGeoJSONResponseWriter, PluginInfoTest, TestJsonFacets, TestFaceting, TestAnalyzeInfixSuggestions, ExplicitHLLTest, TestSolrDynamicMBean, TestBM25SimilarityFactory, TestLRUStatsCache, DirectUpdateHandlerTest, TestDynamicFieldCollectionResource, JSONWriterTest, SimplePostToolTest, PolyFieldTest, SortSpecParsingTest, TestDistribDocBasedVersion, CursorPagingTest, CloudExitableDirectoryReaderTest, TestExpandComponent, TestHighFrequencyDictionaryFactory, TestObjectReleaseTracker, TestStressLucene, TestReplicationHandlerBackup, TestSubQueryTransformer, CloudMLTQParserTest, HighlighterMaxOffsetTest, CheckHdfsIndexTest, PeerSyncWithIndexFingerprintCachingTest, TestSha256AuthenticationProvider, SuggesterFSTTest, TestRandomDVFaceting, TestSweetSpotSimilarityFactory, SolrCLIZkUtilsTest, MoreLikeThisHandlerTest, HLLSerializationTest, ChangedSchemaMergeTest, TestRawResponseWriter, TestSolrCloudWithSecureImpersonation, TestFunctionQuery, RecoveryAfterSoftCommitTest, TestZkChroot, ShardRoutingCustomTest, AutoCommitTest, TestDistributedGrouping, ZkControllerTest, TestJoin, TestReload, DistributedTermsComponentTest, TestCoreContainer, SimpleFacetsTest, TestGroupingSearch, BadIndexSchemaTest, TestSort, TestFiltering, TestIndexSearcher, SoftAutoCommitTest, CurrencyFieldOpenExchangeTest, DistributedQueryElevationComponentTest, TestExtendedDismaxParser, DocValuesTest, TestWordDelimiterFilterFactory, DirectUpdateHandlerOptimizeTest, DocValuesMultiTest, TestSurroundQueryParser, StandardRequestHandlerTest, DirectSolrSpellCheckerTest, TestReversedWildcardFilterFactory, DocumentAnalysisRequestHandlerTest, TestValueSourceCache, PathHierarchyTokenizerFactoryTest, RequiredFieldsTest, TestSolrQueryParser, IndexSchemaRuntimeFieldTest, RegexBoostProcessorTest, TestCollationField, ReturnFieldsTest, MBeansHandlerTest, TestPHPSerializedResponseWriter, CSVRequestHandlerTest, TestLFUCache, TestLuceneMatchVersion, EchoParamsTest, TestLMDirichletSimilarityFactory, TestLMJelinekMercerSimilarityFactory, TestJmxMonitoredMap, TestFastOutputStream, OpenExchangeRatesOrgProviderTest, URLClassifyProcessorTest, TestFastLRUCache, ChaosMonkeyNothingIsSafeTest, BaseCdcrDistributedZkTest, CdcrBootstrapTest, ConnectionManagerTest, CustomCollectionTest, DistribJoinFromCollectionTest, DistributedVersionInfoTest, LeaderFailureAfterFreshStartTest, LeaderInitiatedRecoveryOnCommitTest, MigrateRouteKeyTest, OutOfBoxZkACLAndCredentialsProvidersTest, OverriddenZkACLAndCredentialsProvidersTest, OverseerCollectionConfigSetProcessorTest, OverseerStatusTest, OverseerTaskQueueTest, RemoteQueryErrorTest, ReplaceNodeTest, RollingRestartTest, SSLMigrationTest, SaslZkACLProviderTest, SolrXmlInZkTest, TestCloudInspectUtil, TestCloudPseudoReturnFields, TestCloudRecovery, TestLocalFSCloudBackupRestore, TestRandomFlRTGCloud, TestRequestStatusCollectionAPI, TestSolrCloudWithDelegationTokens, TestSolrCloudWithKerberosAlt, TriLevelCompositeIdRoutingTest, HdfsRecoveryZkTest]
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=HdfsRecoveryZkTest -Dtests.seed=8B11045FDE87FCC5 -Dtests.slow=true -Dtests.locale=zh-SG -Dtests.timezone=Australia/NSW -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] ERROR 0.00s J0 | HdfsRecoveryZkTest (suite) <<<
[junit4] > Throwable #1: java.lang.AssertionError: ObjectTracker found 1 object(s) that were not released!!! [HdfsTransactionLog]
[junit4] > org.apache.solr.common.util.ObjectReleaseTracker$ObjectTrackerException
[junit4] > at org.apache.solr.common.util.ObjectReleaseTracker.track(ObjectReleaseTracker.java:43)
[junit4] > at org.apache.solr.update.HdfsTransactionLog.<init>(HdfsTransactionLog.java:130)
[junit4] > at org.apache.solr.update.HdfsUpdateLog.init(HdfsUpdateLog.java:202)
[junit4] > at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:137)
[junit4] > at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:94)
[junit4] > at org.apache.solr.update.DirectUpdateHandler2.<init>(DirectUpdateHandler2.java:102)
[junit4] > at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
[junit4] > at org.apache.solr.core.SolrCore.createInstance(SolrCore.java:705)
[junit4] > at org.apache.solr.core.SolrCore.createUpdateHandler(SolrCore.java:767)
[junit4] > at org.apache.solr.core.SolrCore.initUpdateHandler(SolrCore.java:1006)
[junit4] > at org.apache.solr.core.SolrCore.<init>(SolrCore.java:871)
[junit4] > at org.apache.solr.core.SolrCore.<init>(SolrCore.java:775)
[junit4] > at org.apache.solr.core.CoreContainer.create(CoreContainer.java:842)
[junit4] > at org.apache.solr.core.CoreContainer.lambda$load$0(CoreContainer.java:498)
[junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] > at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] > at __randomizedtesting.SeedInfo.seed([8B11045FDE87FCC5]:0)
[junit4] > at org.apache.solr.SolrTestCaseJ4.teardownTestCases(SolrTestCaseJ4.java:260)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] Completed [519/658 (2!)] on J0 in 50.43s, 1 test, 1 failure <<< FAILURES!
[...truncated 11501 lines...]
-validate-source-patterns:
[source-patterns] nocommit: solr/core/src/test/org/apache/solr/cloud/DocValuesNotIndexedTest.java
BUILD FAILED
/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/build.xml:765: The following error occurred while executing this line:
/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/build.xml:130: Found 1 violations in source files (nocommit).
Total time: 90 minutes 13 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
[WARNINGS] Skipping publisher since build result is FAILURE
Recording test results
Email was triggered for: Failure - Any
Sending email for trigger: Failure - Any