You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2017/03/07 09:23:18 UTC
[JENKINS] Lucene-Solr-6.x-Solaris (64bit/jdk1.8.0) - Build # 709 -
Failure!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Solaris/709/
Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseG1GC
All tests passed
Build Log:
[...truncated 68150 lines...]
-ecj-javadoc-lint-src:
[mkdir] Created dir: /var/tmp/ecj775381538
[ecj-lint] Compiling 1062 source files to /var/tmp/ecj775381538
[ecj-lint] invalid Class-Path header in manifest of jar file: /export/home/jenkins/.ivy2/cache/org.restlet.jee/org.restlet/jars/org.restlet-2.3.0.jar
[ecj-lint] invalid Class-Path header in manifest of jar file: /export/home/jenkins/.ivy2/cache/org.restlet.jee/org.restlet.ext.servlet/jars/org.restlet.ext.servlet-2.3.0.jar
[ecj-lint] ----------
[ecj-lint] 1. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/cloud/Assign.java (at line 101)
[ecj-lint] Collections.sort(shardIdNames, (o1, o2) -> {
[ecj-lint] ^^^^^^^^^^^
[ecj-lint] (Recovered) Internal inconsistency detected during lambda shape analysis
[ecj-lint] ----------
[ecj-lint] 2. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/cloud/Assign.java (at line 101)
[ecj-lint] Collections.sort(shardIdNames, (o1, o2) -> {
[ecj-lint] ^^^^^^^^^^^
[ecj-lint] (Recovered) Internal inconsistency detected during lambda shape analysis
[ecj-lint] ----------
[ecj-lint] 3. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/cloud/Assign.java (at line 101)
[ecj-lint] Collections.sort(shardIdNames, (o1, o2) -> {
[ecj-lint] ^^^^^^^^^^^
[ecj-lint] (Recovered) Internal inconsistency detected during lambda shape analysis
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 4. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/cloud/rule/ReplicaAssigner.java (at line 212)
[ecj-lint] Collections.sort(sortedLiveNodes, (n1, n2) -> {
[ecj-lint] ^^^^^^^^^^^
[ecj-lint] (Recovered) Internal inconsistency detected during lambda shape analysis
[ecj-lint] ----------
[ecj-lint] 5. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/cloud/rule/ReplicaAssigner.java (at line 212)
[ecj-lint] Collections.sort(sortedLiveNodes, (n1, n2) -> {
[ecj-lint] ^^^^^^^^^^^
[ecj-lint] (Recovered) Internal inconsistency detected during lambda shape analysis
[ecj-lint] ----------
[ecj-lint] 6. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/cloud/rule/ReplicaAssigner.java (at line 212)
[ecj-lint] Collections.sort(sortedLiveNodes, (n1, n2) -> {
[ecj-lint] ^^^^^^^^^^^
[ecj-lint] (Recovered) Internal inconsistency detected during lambda shape analysis
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 7. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/core/CoreContainer.java (at line 917)
[ecj-lint] core = new SolrCore(dcore, coreConfig);
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'core' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 8. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/core/HdfsDirectoryFactory.java (at line 233)
[ecj-lint] dir = new BlockDirectory(path, hdfsDir, cache, null, blockCacheReadEnabled, false, cacheMerges, cacheReadOnce);
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'dir' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 9. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/handler/AnalysisRequestHandlerBase.java (at line 120)
[ecj-lint] reader = cfiltfac.create(reader);
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'reader' is not closed at this location
[ecj-lint] ----------
[ecj-lint] 10. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/handler/AnalysisRequestHandlerBase.java (at line 144)
[ecj-lint] return namedList;
[ecj-lint] ^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'listBasedTokenStream' is not closed at this location
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 11. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/handler/ClassifyStream.java (at line 88)
[ecj-lint] SolrCore solrCore = (SolrCore) solrCoreObj;
[ecj-lint] ^^^^^^^^
[ecj-lint] Resource leak: 'solrCore' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 12. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/handler/ReplicationHandler.java (at line 1236)
[ecj-lint] DirectoryReader reader = s==null ? null : s.get().getIndexReader();
[ecj-lint] ^^^^^^
[ecj-lint] Resource leak: 'reader' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 13. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/handler/component/ExpandComponent.java (at line 222)
[ecj-lint] UninvertingReader uninvertingReader = new UninvertingReader(new ReaderWrapper(searcher.getSlowAtomicReader(), field), mapping);
[ecj-lint] ^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'uninvertingReader' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 14. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/handler/sql/SolrTable.java (at line 507)
[ecj-lint] ParallelStream parallelStream = new ParallelStream(zk, collection, tupleStream, numWorkers, comp);
[ecj-lint] ^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'parallelStream' is never closed
[ecj-lint] ----------
[ecj-lint] 15. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/handler/sql/SolrTable.java (at line 719)
[ecj-lint] ParallelStream parallelStream = new ParallelStream(zkHost, collection, tupleStream, numWorkers, comp);
[ecj-lint] ^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'parallelStream' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 16. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/highlight/DefaultSolrHighlighter.java (at line 554)
[ecj-lint] tvWindowStream = new OffsetWindowTokenFilter(tvStream);
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'tvWindowStream' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 17. ERROR in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/request/NumericFacets.java (at line 55)
[ecj-lint] import org.apache.solr.util.DateMathParser;
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] The import org.apache.solr.util.DateMathParser is never used
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 18. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/request/SimpleFacets.java (at line 920)
[ecj-lint] fastForRandomSet = new HashDocSet(sset.getDocs(), 0, sset.size());
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'fastForRandomSet' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 19. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/response/BinaryResponseWriter.java (at line 51)
[ecj-lint] new JavaBinCodec(resolver).setWritableDocFields(resolver).marshal(response.getValues(), out);
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: '<unassigned Closeable value>' is never closed
[ecj-lint] ----------
[ecj-lint] 20. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/response/BinaryResponseWriter.java (at line 163)
[ecj-lint] new JavaBinCodec(resolver).setWritableDocFields(resolver).marshal(rsp.getValues(), out);
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: '<unassigned Closeable value>' is never closed
[ecj-lint] ----------
[ecj-lint] 21. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/response/BinaryResponseWriter.java (at line 166)
[ecj-lint] return (NamedList<Object>) new JavaBinCodec(resolver).unmarshal(in);
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: '<unassigned Closeable value>' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 22. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/response/SmileResponseWriter.java (at line 33)
[ecj-lint] new SmileWriter(out, request, response).writeResponse();
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: '<unassigned Closeable value>' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 23. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/schema/OpenExchangeRatesOrgProvider.java (at line 146)
[ecj-lint] ratesJsonStream = resourceLoader.openResource(ratesFileLocation);
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'ratesJsonStream' is not closed at this location
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 24. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/search/CollapsingQParserPlugin.java (at line 1185)
[ecj-lint] UninvertingReader uninvertingReader = new UninvertingReader(new ReaderWrapper(searcher.getSlowAtomicReader(), collapseField), mapping);
[ecj-lint] ^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'uninvertingReader' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 25. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/search/CursorMark.java (at line 188)
[ecj-lint] pieces = (List<Object>) new JavaBinCodec().unmarshal(in);
[ecj-lint] ^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: '<unassigned Closeable value>' is never closed
[ecj-lint] ----------
[ecj-lint] 26. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/search/CursorMark.java (at line 265)
[ecj-lint] new JavaBinCodec().marshal(marshalledValues, out);
[ecj-lint] ^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: '<unassigned Closeable value>' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 27. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/search/DocSlice.java (at line 145)
[ecj-lint] HashDocSet h = new HashDocSet(docs,offset,len);
[ecj-lint] ^
[ecj-lint] Resource leak: 'h' is never closed
[ecj-lint] ----------
[ecj-lint] 28. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/search/DocSlice.java (at line 154)
[ecj-lint] HashDocSet h = new HashDocSet(docs,offset,len);
[ecj-lint] ^
[ecj-lint] Resource leak: 'h' is never closed
[ecj-lint] ----------
[ecj-lint] 29. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/search/DocSlice.java (at line 163)
[ecj-lint] HashDocSet h = new HashDocSet(docs,offset,len);
[ecj-lint] ^
[ecj-lint] Resource leak: 'h' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 30. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/search/function/OrdFieldSource.java (at line 78)
[ecj-lint] SolrIndexSearcher is = (SolrIndexSearcher) o;
[ecj-lint] ^^
[ecj-lint] Resource leak: 'is' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 31. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/search/function/ReverseOrdFieldSource.java (at line 78)
[ecj-lint] SolrIndexSearcher is = (SolrIndexSearcher) o;
[ecj-lint] ^^
[ecj-lint] Resource leak: 'is' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 32. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/servlet/SolrDispatchFilter.java (at line 263)
[ecj-lint] throw new SolrException(ErrorCode.SERVER_ERROR, "Error occurred while loading solr.xml from zookeeper", e);
[ecj-lint] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[ecj-lint] Resource leak: 'loader' is not closed at this location
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 33. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/update/CdcrTransactionLog.java (at line 98)
[ecj-lint] ChannelFastInputStream is = new ChannelFastInputStream(channel, pos);
[ecj-lint] ^^
[ecj-lint] Resource leak: 'is' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 34. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/update/HdfsTransactionLog.java (at line 188)
[ecj-lint] LogCodec codec = new LogCodec(resolver);
[ecj-lint] ^^^^^
[ecj-lint] Resource leak: 'codec' is never closed
[ecj-lint] ----------
[ecj-lint] 35. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/update/HdfsTransactionLog.java (at line 258)
[ecj-lint] LogCodec codec = new LogCodec(resolver);
[ecj-lint] ^^^^^
[ecj-lint] Resource leak: 'codec' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 36. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/update/TransactionLog.java (at line 226)
[ecj-lint] ChannelFastInputStream is = new ChannelFastInputStream(channel, pos);
[ecj-lint] ^^
[ecj-lint] Resource leak: 'is' is never closed
[ecj-lint] ----------
[ecj-lint] 37. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/update/TransactionLog.java (at line 226)
[ecj-lint] ChannelFastInputStream is = new ChannelFastInputStream(channel, pos);
[ecj-lint] ^^
[ecj-lint] Resource leak: 'is' is never closed
[ecj-lint] ----------
[ecj-lint] 38. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/update/TransactionLog.java (at line 258)
[ecj-lint] LogCodec codec = new LogCodec(resolver);
[ecj-lint] ^^^^^
[ecj-lint] Resource leak: 'codec' is never closed
[ecj-lint] ----------
[ecj-lint] 39. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/update/TransactionLog.java (at line 273)
[ecj-lint] LogCodec codec = new LogCodec(resolver);
[ecj-lint] ^^^^^
[ecj-lint] Resource leak: 'codec' is never closed
[ecj-lint] ----------
[ecj-lint] 40. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/update/TransactionLog.java (at line 527)
[ecj-lint] LogCodec codec = new LogCodec(resolver);
[ecj-lint] ^^^^^
[ecj-lint] Resource leak: 'codec' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 41. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/update/processor/UpdateRequestProcessor.java (at line 85)
[ecj-lint] UpdateRequestProcessor p = this;
[ecj-lint] ^
[ecj-lint] Resource leak: 'p' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 42. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/util/SimplePostTool.java (at line 655)
[ecj-lint] BAOS bos = new BAOS();
[ecj-lint] ^^^
[ecj-lint] Resource leak: 'bos' is never closed
[ecj-lint] ----------
[ecj-lint] 43. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/util/SimplePostTool.java (at line 655)
[ecj-lint] BAOS bos = new BAOS();
[ecj-lint] ^^^
[ecj-lint] Resource leak: 'bos' is never closed
[ecj-lint] ----------
[ecj-lint] ----------
[ecj-lint] 44. WARNING in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/core/src/java/org/apache/solr/util/SolrLogLayout.java (at line 149)
[ecj-lint] SolrQueryRequest req = requestInfo == null ? null : requestInfo.getReq();
[ecj-lint] ^^^
[ecj-lint] Resource leak: 'req' is never closed
[ecj-lint] ----------
[ecj-lint] 44 problems (1 error, 43 warnings)
BUILD FAILED
/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/build.xml:775: The following error occurred while executing this line:
/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/build.xml:101: The following error occurred while executing this line:
/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build.xml:686: The following error occurred while executing this line:
/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/lucene/common-build.xml:2004: The following error occurred while executing this line:
/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/lucene/common-build.xml:2043: Compile failed; see the compiler error output for details.
Total time: 92 minutes 12 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
[JENKINS] Lucene-Solr-6.x-Solaris (64bit/jdk1.8.0) - Build # 711 -
Still Unstable!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Solaris/711/
Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: org.apache.solr.security.hadoop.TestDelegationWithHadoopAuth.testDelegationTokenRenew
Error Message:
expected:<200> but was:<403>
Stack Trace:
java.lang.AssertionError: expected:<200> but was:<403>
at __randomizedtesting.SeedInfo.seed([4A2C8E19EED5E8D9:7DB77A07D619357D]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.junit.Assert.assertEquals(Assert.java:456)
at org.apache.solr.security.hadoop.TestDelegationWithHadoopAuth.renewDelegationToken(TestDelegationWithHadoopAuth.java:118)
at org.apache.solr.security.hadoop.TestDelegationWithHadoopAuth.verifyDelegationTokenRenew(TestDelegationWithHadoopAuth.java:302)
at org.apache.solr.security.hadoop.TestDelegationWithHadoopAuth.testDelegationTokenRenew(TestDelegationWithHadoopAuth.java:319)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 10904 lines...]
[junit4] Suite: org.apache.solr.security.hadoop.TestDelegationWithHadoopAuth
[junit4] 2> Creating dataDir: /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J1/temp/solr.security.hadoop.TestDelegationWithHadoopAuth_4A2C8E19EED5E8D9-001/init-core-data-001
[junit4] 2> 19715 INFO (SUITE-TestDelegationWithHadoopAuth-seed#[4A2C8E19EED5E8D9]-worker) [ ] o.a.s.SolrTestCaseJ4 Using TrieFields
[junit4] 2> 19717 INFO (SUITE-TestDelegationWithHadoopAuth-seed#[4A2C8E19EED5E8D9]-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> 19719 INFO (SUITE-TestDelegationWithHadoopAuth-seed#[4A2C8E19EED5E8D9]-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/J1/temp/solr.security.hadoop.TestDelegationWithHadoopAuth_4A2C8E19EED5E8D9-001/tempDir-001
[junit4] 2> 19729 INFO (SUITE-TestDelegationWithHadoopAuth-seed#[4A2C8E19EED5E8D9]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 19732 INFO (Thread-17) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 19732 INFO (Thread-17) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 19844 INFO (SUITE-TestDelegationWithHadoopAuth-seed#[4A2C8E19EED5E8D9]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:47992
[junit4] 2> 20035 INFO (jetty-launcher-15-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 20037 INFO (jetty-launcher-15-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@359dc0e8{/solr,null,AVAILABLE}
[junit4] 2> 20040 INFO (jetty-launcher-15-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@5d9200c4{HTTP/1.1,[http/1.1]}{127.0.0.1:36864}
[junit4] 2> 20040 INFO (jetty-launcher-15-thread-1) [ ] o.e.j.s.Server Started @22712ms
[junit4] 2> 20040 INFO (jetty-launcher-15-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=36864}
[junit4] 2> 20040 ERROR (jetty-launcher-15-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 20040 INFO (jetty-launcher-15-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 20048 INFO (jetty-launcher-15-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.5.0
[junit4] 2> 20048 INFO (jetty-launcher-15-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 20048 INFO (jetty-launcher-15-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 20048 INFO (jetty-launcher-15-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-03-08T02:16:44.544Z
[junit4] 2> 20049 INFO (jetty-launcher-15-thread-1) [ ] o.a.s.c.SolrResourceLoader solr home defaulted to 'solr/' (could not find system property or JNDI)
[junit4] 2> 20057 INFO (jetty-launcher-15-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@43b2610e{/solr,null,AVAILABLE}
[junit4] 2> 20060 INFO (jetty-launcher-15-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@9d459ce{HTTP/1.1,[http/1.1]}{127.0.0.1:46865}
[junit4] 2> 20061 INFO (jetty-launcher-15-thread-2) [ ] o.e.j.s.Server Started @22733ms
[junit4] 2> 20061 INFO (jetty-launcher-15-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=46865}
[junit4] 2> 20061 ERROR (jetty-launcher-15-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 20061 INFO (jetty-launcher-15-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.5.0
[junit4] 2> 20062 INFO (jetty-launcher-15-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 20062 INFO (jetty-launcher-15-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 20062 INFO (jetty-launcher-15-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-03-08T02:16:44.558Z
[junit4] 2> 20111 INFO (jetty-launcher-15-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 20129 INFO (jetty-launcher-15-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 20146 INFO (jetty-launcher-15-thread-2) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 20147 INFO (jetty-launcher-15-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:47992/solr
[junit4] 2> 20184 INFO (jetty-launcher-15-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 20186 INFO (jetty-launcher-15-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:47992/solr
[junit4] 2> 20439 INFO (jetty-launcher-15-thread-1) [n:127.0.0.1:36864_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 20442 INFO (jetty-launcher-15-thread-1) [n:127.0.0.1:36864_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:36864_solr
[junit4] 2> 20443 INFO (jetty-launcher-15-thread-2) [n:127.0.0.1:46865_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 20446 INFO (jetty-launcher-15-thread-1) [n:127.0.0.1:36864_solr ] o.a.s.c.Overseer Overseer (id=97579132799549445-127.0.0.1:36864_solr-n_0000000000) starting
[junit4] 2> 20448 INFO (jetty-launcher-15-thread-2) [n:127.0.0.1:46865_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46865_solr
[junit4] 2> 20454 INFO (zkCallback-27-thread-1-processing-n:127.0.0.1:46865_solr) [n:127.0.0.1:46865_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 20457 INFO (zkCallback-26-thread-1-processing-n:127.0.0.1:36864_solr) [n:127.0.0.1:36864_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 20548 INFO (jetty-launcher-15-thread-2) [n:127.0.0.1:46865_solr ] o.a.s.c.CoreContainer Initializing authentication plugin: org.apache.solr.security.HadoopAuthPlugin
[junit4] 2> 20569 INFO (jetty-launcher-15-thread-2) [n:127.0.0.1:46865_solr ] o.a.s.s.HadoopAuthPlugin Params: {delegation-token.token-kind=solr-dt, cookie.domain=127.0.0.1, zk-dt-secret-manager.znodeWorkingPath=solr/security/zkdtsm, signer.secret.provider.zookeeper.path=/token, type=simple, zk-dt-secret-manager.enable=true, signer.secret.provider=zookeeper}
[junit4] 2> 20611 INFO (jetty-launcher-15-thread-1) [n:127.0.0.1:36864_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36864_solr
[junit4] 2> 20755 INFO (jetty-launcher-15-thread-2) [n:127.0.0.1:46865_solr ] o.a.c.f.i.CuratorFrameworkImpl Starting
[junit4] 2> 20757 INFO (jetty-launcher-15-thread-1) [n:127.0.0.1:36864_solr ] o.a.s.c.CoreContainer Initializing authentication plugin: org.apache.solr.security.HadoopAuthPlugin
[junit4] 2> 20760 INFO (zkCallback-27-thread-1-processing-n:127.0.0.1:46865_solr) [n:127.0.0.1:46865_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 20757 INFO (jetty-launcher-15-thread-1) [n:127.0.0.1:36864_solr ] o.a.s.s.HadoopAuthPlugin Params: {delegation-token.token-kind=solr-dt, cookie.domain=127.0.0.1, zk-dt-secret-manager.znodeWorkingPath=solr/security/zkdtsm, signer.secret.provider.zookeeper.path=/token, type=simple, zk-dt-secret-manager.enable=true, signer.secret.provider=zookeeper}
[junit4] 2> 20790 INFO (jetty-launcher-15-thread-1) [n:127.0.0.1:36864_solr ] o.a.c.f.i.CuratorFrameworkImpl Starting
[junit4] 2> 20827 INFO (zkCallback-26-thread-2-processing-n:127.0.0.1:36864_solr) [n:127.0.0.1:36864_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 21682 INFO (jetty-launcher-15-thread-1-EventThread) [n:127.0.0.1:36864_solr ] o.a.c.f.s.ConnectionStateManager State change: CONNECTED
[junit4] 2> 21682 INFO (jetty-launcher-15-thread-2-EventThread) [n:127.0.0.1:46865_solr ] o.a.c.f.s.ConnectionStateManager State change: CONNECTED
[junit4] 2> 22055 INFO (jetty-launcher-15-thread-2) [n:127.0.0.1:46865_solr ] o.a.s.c.CoreContainer PKIAuthenticationPlugin is managing internode requests
[junit4] 2> 22055 INFO (jetty-launcher-15-thread-2) [n:127.0.0.1:46865_solr ] o.a.s.h.c.HttpShardHandlerFactory Reconfiguring the default client with: org.apache.solr.security.PKIAuthenticationPlugin$HttpHeaderClientConfigurer@2f94aa11
[junit4] 2> 22055 INFO (jetty-launcher-15-thread-2) [n:127.0.0.1:46865_solr ] o.a.s.u.UpdateShardHandler Reconfiguring the default client with: org.apache.solr.security.PKIAuthenticationPlugin$HttpHeaderClientConfigurer@2f94aa11
[junit4] 2> 22071 INFO (jetty-launcher-15-thread-1) [n:127.0.0.1:36864_solr ] o.a.s.c.CoreContainer PKIAuthenticationPlugin is managing internode requests
[junit4] 2> 22071 INFO (jetty-launcher-15-thread-1) [n:127.0.0.1:36864_solr ] o.a.s.h.c.HttpShardHandlerFactory Reconfiguring the default client with: org.apache.solr.security.PKIAuthenticationPlugin$HttpHeaderClientConfigurer@65ffb43b
[junit4] 2> 22071 INFO (jetty-launcher-15-thread-1) [n:127.0.0.1:36864_solr ] o.a.s.u.UpdateShardHandler Reconfiguring the default client with: org.apache.solr.security.PKIAuthenticationPlugin$HttpHeaderClientConfigurer@65ffb43b
[junit4] 2> 22119 INFO (jetty-launcher-15-thread-2) [n:127.0.0.1:46865_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.security.hadoop.TestDelegationWithHadoopAuth_4A2C8E19EED5E8D9-001/tempDir-001/node2/.
[junit4] 2> 22227 INFO (jetty-launcher-15-thread-1) [n:127.0.0.1:36864_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.security.hadoop.TestDelegationWithHadoopAuth_4A2C8E19EED5E8D9-001/tempDir-001/node1/.
[junit4] 2> 22385 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenVerify-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDelegationTokenVerify
[junit4] 2> 23028 INFO (qtp1646151721-123) [n:127.0.0.1:46865_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&delegation=GgADZm9vA2ZvbwCKAVqrtFasigFaz8DarAEEFLOnvnZITmjjmh6Rm2elIFw9dj5FB3NvbHItZHQA&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 23029 INFO (qtp1646151721-123) [n:127.0.0.1:46865_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&delegation=GgADZm9vA2ZvbwCKAVqrtFasigFaz8DarAEEFLOnvnZITmjjmh6Rm2elIFw9dj5FB3NvbHItZHQA&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 23065 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenVerify-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23076 INFO (qtp243548230-107) [n:127.0.0.1:36864_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&delegation=GgADZm9vA2ZvbwCKAVqrtFasigFaz8DarAEEFLOnvnZITmjjmh6Rm2elIFw9dj5FB3NvbHItZHQA&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 23094 INFO (qtp243548230-107) [n:127.0.0.1:36864_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&delegation=GgADZm9vA2ZvbwCKAVqrtFasigFaz8DarAEEFLOnvnZITmjjmh6Rm2elIFw9dj5FB3NvbHItZHQA&wt=javabin&version=2} status=0 QTime=18
[junit4] 2> 23122 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenVerify-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 23124 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenVerify-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:47992/solr ready
[junit4] 2> 23131 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenVerify-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23138 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenVerify-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDelegationTokenVerify
[junit4] 2> 23161 INFO (TEST-TestDelegationWithHadoopAuth.testZNodePaths-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testZNodePaths
[junit4] 2> 23198 INFO (TEST-TestDelegationWithHadoopAuth.testZNodePaths-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testZNodePaths
[junit4] 2> 23217 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDelegationTokenCancel
[junit4] 2> 23282 ERROR (qtp1646151721-122) [ ] o.a.h.s.t.d.ZKDelegationTokenSecretManager No node in path [/ZKDTSMTokensRoot/DT_3]
[junit4] 2> 23317 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23328 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 23330 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:47992/solr ready
[junit4] 2> 23337 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23367 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 23369 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:47992/solr ready
[junit4] 2> 23372 ERROR (qtp1646151721-121) [ ] o.a.h.s.t.d.ZKDelegationTokenSecretManager No node in path [/ZKDTSMTokensRoot/DT_4]
[junit4] 2> 23382 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23391 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 23409 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:47992/solr ready
[junit4] 2> 23416 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23419 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenCancel-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDelegationTokenCancel
[junit4] 2> 23442 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenRenewFail-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDelegationTokenRenewFail
[junit4] 2> 23457 WARN (qtp1646151721-121) [ ] o.a.h.s.a.s.AuthenticationFilter Authentication exception: org.apache.hadoop.security.AccessControlException: bar tries to renew a token with renewer foo
[junit4] 2> 23457 WARN (qtp1646151721-121) [ ] o.a.s.s.HadoopAuthPlugin Could not find org.apache.solr.security.authentication.requestcontinues
[junit4] 2> 23457 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenRenewFail-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23460 WARN (qtp243548230-117) [ ] o.a.h.s.a.s.AuthenticationFilter Authentication exception: org.apache.hadoop.security.AccessControlException: bar tries to renew a token with renewer foo
[junit4] 2> 23461 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenRenewFail-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23461 WARN (qtp243548230-117) [ ] o.a.s.s.HadoopAuthPlugin Could not find org.apache.solr.security.authentication.requestcontinues
[junit4] 2> 23471 WARN (qtp1646151721-124) [ ] o.a.h.s.a.s.AuthenticationFilter Authentication exception: org.apache.hadoop.security.AccessControlException: notRenewUser tries to renew a token with renewer renewUser
[junit4] 2> 23472 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenRenewFail-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23472 WARN (qtp1646151721-124) [ ] o.a.s.s.HadoopAuthPlugin Could not find org.apache.solr.security.authentication.requestcontinues
[junit4] 2> 23474 WARN (qtp243548230-118) [ ] o.a.h.s.a.s.AuthenticationFilter Authentication exception: org.apache.hadoop.security.AccessControlException: notRenewUser tries to renew a token with renewer renewUser
[junit4] 2> 23475 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenRenewFail-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23475 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenRenewFail-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDelegationTokenRenewFail
[junit4] 2> 23475 WARN (qtp243548230-118) [ ] o.a.s.s.HadoopAuthPlugin Could not find org.apache.solr.security.authentication.requestcontinues
[junit4] 2> 23499 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenRenew-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDelegationTokenRenew
[junit4] 2> 23508 WARN (qtp1646151721-125) [ ] o.a.h.s.a.s.AuthenticationFilter Authentication exception: org.apache.hadoop.security.AccessControlException: foo is trying to renew a token with wrong password
[junit4] 2> 23509 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenRenew-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23510 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenRenew-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDelegationTokenRenew
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestDelegationWithHadoopAuth -Dtests.method=testDelegationTokenRenew -Dtests.seed=4A2C8E19EED5E8D9 -Dtests.slow=true -Dtests.locale=sl-SI -Dtests.timezone=Asia/Sakhalin -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[junit4] FAILURE 0.04s J1 | TestDelegationWithHadoopAuth.testDelegationTokenRenew <<<
[junit4] > Throwable #1: java.lang.AssertionError: expected:<200> but was:<403>
[junit4] > at __randomizedtesting.SeedInfo.seed([4A2C8E19EED5E8D9:7DB77A07D619357D]:0)
[junit4] > at org.apache.solr.security.hadoop.TestDelegationWithHadoopAuth.renewDelegationToken(TestDelegationWithHadoopAuth.java:118)
[junit4] > at org.apache.solr.security.hadoop.TestDelegationWithHadoopAuth.verifyDelegationTokenRenew(TestDelegationWithHadoopAuth.java:302)
[junit4] > at org.apache.solr.security.hadoop.TestDelegationWithHadoopAuth.testDelegationTokenRenew(TestDelegationWithHadoopAuth.java:319)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 23512 WARN (qtp1646151721-125) [ ] o.a.s.s.HadoopAuthPlugin Could not find org.apache.solr.security.authentication.requestcontinues
[junit4] 2> 23539 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenSolrClient-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDelegationTokenSolrClient
[junit4] 2> 23558 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationTokenSolrClient-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth=; Domain=127.0.0.1; Expires= et, 01-jan.-1970 00:00:00 GMT; HttpOnly". Invalid 'expires' attribute: et, 01-jan.-1970 00:00:00 GMT
[junit4] 2> 23568 INFO (qtp1646151721-121) [n:127.0.0.1:46865_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&delegation=GgADZm9vA2ZvbwCKAVqrtFqmigFaz8DepggEFHJ-ODBBNwVRPQy1PT0XUdnPCBhCB3NvbHItZHQA&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 23569 INFO (qtp1646151721-121) [n:127.0.0.1:46865_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&delegation=GgADZm9vA2ZvbwCKAVqrtFqmigFaz8DepggEFHJ-ODBBNwVRPQy1PT0XUdnPCBhCB3NvbHItZHQA&wt=javabin&version=2} status=0 QTime=1
[junit4] 2> 23570 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationTokenSolrClient-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDelegationTokenSolrClient
[junit4] IGNOR/A 0.00s J1 | TestDelegationWithHadoopAuth.testDelegationTokenCancelFail
[junit4] > Assumption #1: 'awaitsfix' test group is disabled (@AwaitsFix(bugUrl=https://issues.apache.org/jira/browse/HADOOP-14044))
[junit4] 2> 23589 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationOtherOp-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDelegationOtherOp
[junit4] 2> 23602 INFO (qtp1646151721-121) [n:127.0.0.1:46865_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params op=someSolrOperation&action=LIST&user.name=foo&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 23602 INFO (qtp1646151721-121) [n:127.0.0.1:46865_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={op=someSolrOperation&action=LIST&user.name=foo&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 23603 WARN (TEST-TestDelegationWithHadoopAuth.testDelegationOtherOp-seed#[4A2C8E19EED5E8D9]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=foo&p=foo&t=simple-dt&e=1488975408097&s=clTxnnlSiojeeXs68y1VcaMSkWU="; Domain=127.0.0.1; Expires=Sre, 08-mar.-2017 12:16:48 GMT; HttpOnly". Invalid 'expires' attribute: Sre, 08-mar.-2017 12:16:48 GMT
[junit4] 2> 23603 INFO (TEST-TestDelegationWithHadoopAuth.testDelegationOtherOp-seed#[4A2C8E19EED5E8D9]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDelegationOtherOp
[junit4] 2> 23607 INFO (jetty-closer-16-thread-1) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@9d459ce{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 23607 INFO (jetty-closer-16-thread-1) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1493911359
[junit4] 2> 23608 INFO (jetty-closer-16-thread-2) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@5d9200c4{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 23610 INFO (jetty-closer-16-thread-2) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1743706362
[junit4] 2> 23619 INFO (jetty-closer-16-thread-2) [ ] o.a.s.c.Overseer Overseer (id=97579132799549445-127.0.0.1:36864_solr-n_0000000000) closing
[junit4] 2> 23619 INFO (OverseerStateUpdate-97579132799549445-127.0.0.1:36864_solr-n_0000000000) [n:127.0.0.1:36864_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:36864_solr
[junit4] 2> 23628 WARN (zkCallback-27-thread-1-processing-n:127.0.0.1:46865_solr) [n:127.0.0.1:46865_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 23628 INFO (jetty-closer-16-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.node
[junit4] 2> 23628 ERROR (Thread[Thread-37,5,TGRP-TestDelegationWithHadoopAuth]) [n:127.0.0.1:46865_solr ] o.a.h.s.t.d.AbstractDelegationTokenSecretManager ExpiredTokenRemover received java.lang.InterruptedException: sleep interrupted
[junit4] 2> 23647 INFO (jetty-closer-16-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@43b2610e{/solr,null,UNAVAILABLE}
[junit4] 2> 25128 WARN (zkCallback-26-thread-2-processing-n:127.0.0.1:36864_solr) [n:127.0.0.1:36864_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 25128 INFO (jetty-closer-16-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.node
[junit4] 2> 25128 ERROR (Thread[Thread-39,5,TGRP-TestDelegationWithHadoopAuth]) [n:127.0.0.1:36864_solr ] o.a.h.s.t.d.AbstractDelegationTokenSecretManager ExpiredTokenRemover received java.lang.InterruptedException: sleep interrupted
[junit4] 2> 25134 INFO (jetty-closer-16-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@359dc0e8{/solr,null,UNAVAILABLE}
[junit4] 2> 25141 INFO (SUITE-TestDelegationWithHadoopAuth-seed#[4A2C8E19EED5E8D9]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:47992 47992
[junit4] 2> 25192 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxnFactory Ignoring unexpected runtime exception
[junit4] 2> java.nio.channels.CancelledKeyException
[junit4] 2> at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73)
[junit4] 2> at sun.nio.ch.SelectionKeyImpl.readyOps(SelectionKeyImpl.java:87)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:187)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 25194 INFO (Thread-17) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:47992 47992
[junit4] 2> 25196 WARN (Thread-17) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 6 /solr/aliases.json
[junit4] 2> 6 /solr/clusterprops.json
[junit4] 2> 2 /solr/security.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 6 /solr/clusterstate.json
[junit4] 2> 3 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMKeyIdRoot
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMTokensRoot/DT_7
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMTokensRoot/DT_6
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMTokensRoot/DT_8
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMMasterKeyRoot/DK_1
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMTokensRoot/DT_1
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMTokensRoot/DT_3
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMMasterKeyRoot/DK_2
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMTokensRoot/DT_2
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMTokensRoot/DT_5
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMMasterKeyRoot/DK_4
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMTokensRoot/DT_4
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMSeqNumRoot
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 6 /solr/live_nodes
[junit4] 2> 6 /solr/collections
[junit4] 2> 3 /solr/overseer/queue
[junit4] 2> 3 /solr/overseer/collection-queue-work
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMMasterKeyRoot
[junit4] 2> 2 /solr/overseer/queue-work
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMTokensRoot
[junit4] 2>
[junit4] 2> 25197 INFO (SUITE-TestDelegationWithHadoopAuth-seed#[4A2C8E19EED5E8D9]-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.security.hadoop.TestDelegationWithHadoopAuth_4A2C8E19EED5E8D9-001
[junit4] 2> Mar 08, 2017 2:16:49 AM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 2 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=FastCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=FAST, chunkSize=10, maxDocsPerChunk=579, blockSize=414), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=FAST, chunkSize=10, blockSize=414)), sim=RandomSimilarity(queryNorm=false,coord=crazy): {}, locale=sl-SI, timezone=Asia/Sakhalin
[junit4] 2> NOTE: SunOS 5.11 amd64/Oracle Corporation 1.8.0_121 (64-bit)/cpus=3,threads=1,free=31913368,total=97320960
[junit4] 2> NOTE: All tests run in this JVM: [EchoParamsTest, TestEmbeddedSolrServerSchemaAPI, TestObjectReleaseTracker, SuggesterWFSTTest, TestTrieFacet, TestTrie, TestSolrQueryParserResource, TestDelegationWithHadoopAuth]
[junit4] Completed [10/697 (1!)] on J1 in 6.02s, 8 tests, 1 failure, 1 skipped <<< FAILURES!
[...truncated 64930 lines...]
[JENKINS] Lucene-Solr-6.x-Solaris (64bit/jdk1.8.0) - Build # 710 -
Still unstable!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Solaris/710/
Java: 64bit/jdk1.8.0 -XX:+UseCompressedOops -XX:+UseParallelGC
1 tests failed.
FAILED: org.apache.solr.cloud.CdcrBootstrapTest.testBootstrapWithSourceCluster
Error Message:
Document mismatch on target after sync expected:<2000> but was:<1000>
Stack Trace:
java.lang.AssertionError: Document mismatch on target after sync expected:<2000> but was:<1000>
at __randomizedtesting.SeedInfo.seed([48351F47AE662088:91634E83AD0233C2]: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:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 12520 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/J0/temp/solr.cloud.CdcrBootstrapTest_48351F47AE662088-001/init-core-data-001
[junit4] 2> 1703238 INFO (SUITE-CdcrBootstrapTest-seed#[48351F47AE662088]-worker) [ ] o.a.s.SolrTestCaseJ4 Using TrieFields
[junit4] 2> 1703239 INFO (SUITE-CdcrBootstrapTest-seed#[48351F47AE662088]-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> 1703241 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[48351F47AE662088]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testBootstrapWithSourceCluster
[junit4] 2> 1703241 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[48351F47AE662088]) [ ] 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/J0/temp/solr.cloud.CdcrBootstrapTest_48351F47AE662088-001/cdcr-target-001
[junit4] 2> 1703241 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[48351F47AE662088]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 1703241 INFO (Thread-5683) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1703241 INFO (Thread-5683) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 1703341 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[48351F47AE662088]) [ ] o.a.s.c.ZkTestServer start zk server on port:61550
[junit4] 2> 1703349 INFO (jetty-launcher-3504-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1703351 INFO (jetty-launcher-3504-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@69445049{/solr,null,AVAILABLE}
[junit4] 2> 1703351 INFO (jetty-launcher-3504-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@729ea8fe{HTTP/1.1,[http/1.1]}{127.0.0.1:44270}
[junit4] 2> 1703351 INFO (jetty-launcher-3504-thread-1) [ ] o.e.j.s.Server Started @1708304ms
[junit4] 2> 1703351 INFO (jetty-launcher-3504-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=44270}
[junit4] 2> 1703352 ERROR (jetty-launcher-3504-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1703352 INFO (jetty-launcher-3504-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.5.0
[junit4] 2> 1703352 INFO (jetty-launcher-3504-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1703352 INFO (jetty-launcher-3504-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1703352 INFO (jetty-launcher-3504-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-03-07T17:13:01.921Z
[junit4] 2> 1703354 INFO (jetty-launcher-3504-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1703361 INFO (jetty-launcher-3504-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1703362 INFO (jetty-launcher-3504-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:61550/solr
[junit4] 2> 1703397 INFO (jetty-launcher-3504-thread-1) [n:127.0.0.1:44270_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 1703398 INFO (jetty-launcher-3504-thread-1) [n:127.0.0.1:44270_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:44270_solr
[junit4] 2> 1703400 INFO (jetty-launcher-3504-thread-1) [n:127.0.0.1:44270_solr ] o.a.s.c.Overseer Overseer (id=97576994852765699-127.0.0.1:44270_solr-n_0000000000) starting
[junit4] 2> 1703410 INFO (jetty-launcher-3504-thread-1) [n:127.0.0.1:44270_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44270_solr
[junit4] 2> 1703413 INFO (OverseerStateUpdate-97576994852765699-127.0.0.1:44270_solr-n_0000000000) [n:127.0.0.1:44270_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1703476 INFO (jetty-launcher-3504-thread-1) [n:127.0.0.1:44270_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.CdcrBootstrapTest_48351F47AE662088-001/cdcr-target-001/node1/.
[junit4] 1> Target zkHost = 127.0.0.1:61550/solr
[junit4] 2> 1703842 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[48351F47AE662088]) [ ] 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/J0/temp/solr.cloud.CdcrBootstrapTest_48351F47AE662088-001/cdcr-source-001
[junit4] 2> 1703842 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[48351F47AE662088]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 1703842 INFO (Thread-5693) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1703842 INFO (Thread-5693) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 1703845 WARN (Thread-5693) [ ] o.a.z.j.MBeanRegistry Failed to register MBean StandaloneServer_port-1
[junit4] 2> 1703845 WARN (Thread-5693) [ ] 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> 1703942 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[48351F47AE662088]) [ ] o.a.s.c.ZkTestServer start zk server on port:43008
[junit4] 2> 1703951 INFO (jetty-launcher-3516-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1703953 INFO (jetty-launcher-3516-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@7b4a0cb9{/solr,null,AVAILABLE}
[junit4] 2> 1703953 INFO (jetty-launcher-3516-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@2f209abc{HTTP/1.1,[http/1.1]}{127.0.0.1:55396}
[junit4] 2> 1703953 INFO (jetty-launcher-3516-thread-1) [ ] o.e.j.s.Server Started @1708907ms
[junit4] 2> 1703953 INFO (jetty-launcher-3516-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=55396}
[junit4] 2> 1703954 ERROR (jetty-launcher-3516-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1703954 INFO (jetty-launcher-3516-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.5.0
[junit4] 2> 1703954 INFO (jetty-launcher-3516-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1703954 INFO (jetty-launcher-3516-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1703954 INFO (jetty-launcher-3516-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-03-07T17:13:02.523Z
[junit4] 2> 1703957 INFO (jetty-launcher-3516-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1703963 INFO (jetty-launcher-3516-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1703964 INFO (jetty-launcher-3516-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:43008/solr
[junit4] 2> 1704004 INFO (jetty-launcher-3516-thread-1) [n:127.0.0.1:55396_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 1704006 INFO (jetty-launcher-3516-thread-1) [n:127.0.0.1:55396_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:55396_solr
[junit4] 2> 1704007 INFO (jetty-launcher-3516-thread-1) [n:127.0.0.1:55396_solr ] o.a.s.c.Overseer Overseer (id=97576994892218371-127.0.0.1:55396_solr-n_0000000000) starting
[junit4] 2> 1704019 INFO (jetty-launcher-3516-thread-1) [n:127.0.0.1:55396_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55396_solr
[junit4] 2> 1704022 INFO (OverseerStateUpdate-97576994892218371-127.0.0.1:55396_solr-n_0000000000) [n:127.0.0.1:55396_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1704130 INFO (jetty-launcher-3516-thread-1) [n:127.0.0.1:55396_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.CdcrBootstrapTest_48351F47AE662088-001/cdcr-source-001/node1/.
[junit4] 2> 1704546 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[48351F47AE662088]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1704548 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[48351F47AE662088]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:43008/solr ready
[junit4] 2> 1704551 INFO (qtp230876729-19287) [n:127.0.0.1:55396_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> 1704555 INFO (OverseerThreadFactory-7417-thread-1-processing-n:127.0.0.1:55396_solr) [n:127.0.0.1:55396_solr ] o.a.s.c.CreateCollectionCmd Create collection cdcr-source
[junit4] 2> 1704663 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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> 1704770 INFO (zkCallback-3523-thread-2-processing-n:127.0.0.1:55396_solr) [n:127.0.0.1:55396_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> 1705675 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.5.0
[junit4] 2> 1705680 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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> 1705682 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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> 1705684 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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> 1705685 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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> 1705690 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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> 1705691 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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> 1705691 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 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/J0/temp/solr.cloud.CdcrBootstrapTest_48351F47AE662088-001/cdcr-source-001/node1/cdcr-source_shard1_replica1], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.CdcrBootstrapTest_48351F47AE662088-001/cdcr-source-001/node1/./cdcr-source_shard1_replica1/data/]
[junit4] 2> 1705761 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.CdcrUpdateLog
[junit4] 2> 1705762 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1705762 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1705762 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1705764 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@61a62010[cdcr-source_shard1_replica1] main]
[junit4] 2> 1705765 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/cdcr-source
[junit4] 2> 1705765 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 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> 1705766 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 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> 1705767 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Current schema version 0 is already the latest
[junit4] 2> 1705767 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1705774 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.h.CdcrBufferStateManager Created znode /collections/cdcr-source/cdcr/state/buffer
[junit4] 2> 1705779 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.h.CdcrProcessStateManager Created znode /collections/cdcr-source/cdcr/state/process
[junit4] 2> 1705803 INFO (searcherExecutor-7420-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.SolrCore [cdcr-source_shard1_replica1] Registered new searcher Searcher@61a62010[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1705803 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1561231920329654272
[junit4] 2> 1705812 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1705812 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1705812 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:55396/solr/cdcr-source_shard1_replica1/
[junit4] 2> 1705812 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1705812 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.SyncStrategy http://127.0.0.1:55396/solr/cdcr-source_shard1_replica1/ has no replicas
[junit4] 2> 1705812 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 1705818 INFO (zkCallback-3523-thread-2-processing-n:127.0.0.1:55396_solr) [n:127.0.0.1:55396_solr ] o.a.s.h.CdcrLeaderStateManager Received new leader state @ cdcr-source:shard1
[junit4] 2> 1705820 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:55396/solr/cdcr-source_shard1_replica1/ shard1
[junit4] 2> 1705931 INFO (zkCallback-3523-thread-1-processing-n:127.0.0.1:55396_solr) [n:127.0.0.1:55396_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> 1705981 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 x:cdcr-source_shard1_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1705984 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 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=1322
[junit4] 2> 1705994 INFO (qtp230876729-19287) [n:127.0.0.1:55396_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> 1706090 INFO (zkCallback-3523-thread-3-processing-n:127.0.0.1:55396_solr) [n:127.0.0.1:55396_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> 1706558 INFO (OverseerCollectionConfigSetProcessor-97576994892218371-127.0.0.1:55396_solr-n_0000000000) [n:127.0.0.1:55396_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> 1706996 INFO (qtp230876729-19287) [n:127.0.0.1:55396_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=2446
[junit4] 1> Adding 10 docs with commit=true, numDocs=100
[junit4] 2> 1707010 INFO (qtp230876729-19290) [n:127.0.0.1:55396_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=8
[junit4] 2> 1707013 INFO (qtp230876729-19291) [n:127.0.0.1:55396_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> 1707014 INFO (qtp230876729-19291) [n:127.0.0.1:55396_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@10c4327f
[junit4] 2> 1707025 INFO (qtp230876729-19291) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@233b408d[cdcr-source_shard1_replica1] main]
[junit4] 2> 1707025 INFO (qtp230876729-19291) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1707025 INFO (searcherExecutor-7420-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_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@233b408d[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.5.0):C100)))}
[junit4] 2> 1707026 INFO (qtp230876729-19291) [n:127.0.0.1:55396_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=12
[junit4] 1> Adding 10 docs with commit=true, numDocs=200
[junit4] 2> 1707033 INFO (qtp230876729-19292) [n:127.0.0.1:55396_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> 1707035 INFO (qtp230876729-19285) [n:127.0.0.1:55396_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> 1707035 INFO (qtp230876729-19285) [n:127.0.0.1:55396_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@10c4327f
[junit4] 2> 1707046 INFO (qtp230876729-19285) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@2ab39857[cdcr-source_shard1_replica1] main]
[junit4] 2> 1707046 INFO (searcherExecutor-7420-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_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@2ab39857[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.5.0):C100) Uninverting(_1(6.5.0):C100)))}
[junit4] 2> 1707046 INFO (qtp230876729-19285) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1707046 INFO (qtp230876729-19285) [n:127.0.0.1:55396_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=11
[junit4] 1> Adding 10 docs with commit=true, numDocs=300
[junit4] 2> 1707052 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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> 1707055 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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> 1707055 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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@10c4327f
[junit4] 2> 1707066 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@2b10858d[cdcr-source_shard1_replica1] main]
[junit4] 2> 1707067 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1707067 INFO (searcherExecutor-7420-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_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@2b10858d[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.5.0):C100) Uninverting(_1(6.5.0):C100) Uninverting(_2(6.5.0):C100)))}
[junit4] 2> 1707067 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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=12
[junit4] 1> Adding 10 docs with commit=true, numDocs=400
[junit4] 2> 1707072 INFO (qtp230876729-19287) [n:127.0.0.1:55396_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> 1707074 INFO (qtp230876729-19290) [n:127.0.0.1:55396_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> 1707074 INFO (qtp230876729-19290) [n:127.0.0.1:55396_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@10c4327f
[junit4] 2> 1707087 INFO (qtp230876729-19290) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@4528277e[cdcr-source_shard1_replica1] main]
[junit4] 2> 1707087 INFO (qtp230876729-19290) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1707087 INFO (searcherExecutor-7420-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_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@4528277e[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.5.0):C100) Uninverting(_1(6.5.0):C100) Uninverting(_2(6.5.0):C100) Uninverting(_3(6.5.0):C100)))}
[junit4] 2> 1707087 INFO (qtp230876729-19290) [n:127.0.0.1:55396_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=13
[junit4] 1> Adding 10 docs with commit=true, numDocs=500
[junit4] 2> 1707093 INFO (qtp230876729-19291) [n:127.0.0.1:55396_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> 1707095 INFO (qtp230876729-19292) [n:127.0.0.1:55396_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> 1707095 INFO (qtp230876729-19292) [n:127.0.0.1:55396_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@10c4327f
[junit4] 2> 1707108 INFO (qtp230876729-19292) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@28e62b72[cdcr-source_shard1_replica1] main]
[junit4] 2> 1707108 INFO (qtp230876729-19292) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1707109 INFO (searcherExecutor-7420-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_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@28e62b72[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.5.0):C100) Uninverting(_1(6.5.0):C100) Uninverting(_2(6.5.0):C100) Uninverting(_3(6.5.0):C100) Uninverting(_4(6.5.0):C100)))}
[junit4] 2> 1707109 INFO (qtp230876729-19292) [n:127.0.0.1:55396_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=13
[junit4] 1> Adding 10 docs with commit=true, numDocs=600
[junit4] 2> 1707114 INFO (qtp230876729-19285) [n:127.0.0.1:55396_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> 1707115 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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> 1707115 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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@10c4327f
[junit4] 2> 1707129 INFO (qtp230876729-19288) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@4d84da65[cdcr-source_shard1_replica1] main]
[junit4] 2> 1707129 INFO (qtp230876729-19288) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1707129 INFO (searcherExecutor-7420-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_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@4d84da65[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.5.0):C100) Uninverting(_1(6.5.0):C100) Uninverting(_2(6.5.0):C100) Uninverting(_3(6.5.0):C100) Uninverting(_4(6.5.0):C100) Uninverting(_5(6.5.0):C100)))}
[junit4] 2> 1707129 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=14
[junit4] 1> Adding 10 docs with commit=true, numDocs=700
[junit4] 2> 1707134 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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> 1707136 INFO (qtp230876729-19287) [n:127.0.0.1:55396_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> 1707136 INFO (qtp230876729-19287) [n:127.0.0.1:55396_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@10c4327f
[junit4] 2> 1707150 INFO (qtp230876729-19287) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@315fea2[cdcr-source_shard1_replica1] main]
[junit4] 2> 1707150 INFO (qtp230876729-19287) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1707151 INFO (searcherExecutor-7420-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_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@315fea2[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.5.0):C100) Uninverting(_1(6.5.0):C100) Uninverting(_2(6.5.0):C100) Uninverting(_3(6.5.0):C100) Uninverting(_4(6.5.0):C100) Uninverting(_5(6.5.0):C100) Uninverting(_6(6.5.0):C100)))}
[junit4] 2> 1707151 INFO (qtp230876729-19287) [n:127.0.0.1:55396_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=15
[junit4] 1> Adding 10 docs with commit=true, numDocs=800
[junit4] 2> 1707160 INFO (qtp230876729-19290) [n:127.0.0.1:55396_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> 1707161 INFO (qtp230876729-19291) [n:127.0.0.1:55396_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> 1707161 INFO (qtp230876729-19291) [n:127.0.0.1:55396_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@10c4327f
[junit4] 2> 1707176 INFO (qtp230876729-19291) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@16b02e6[cdcr-source_shard1_replica1] main]
[junit4] 2> 1707176 INFO (qtp230876729-19291) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1707176 INFO (searcherExecutor-7420-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_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@16b02e6[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.5.0):C100) Uninverting(_1(6.5.0):C100) Uninverting(_2(6.5.0):C100) Uninverting(_3(6.5.0):C100) Uninverting(_4(6.5.0):C100) Uninverting(_5(6.5.0):C100) Uninverting(_6(6.5.0):C100) Uninverting(_7(6.5.0):C100)))}
[junit4] 2> 1707177 INFO (qtp230876729-19291) [n:127.0.0.1:55396_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=15
[junit4] 1> Adding 10 docs with commit=true, numDocs=900
[junit4] 2> 1707181 INFO (qtp230876729-19292) [n:127.0.0.1:55396_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> 1707183 INFO (qtp230876729-19285) [n:127.0.0.1:55396_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> 1707183 INFO (qtp230876729-19285) [n:127.0.0.1:55396_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@10c4327f
[junit4] 2> 1707198 INFO (qtp230876729-19285) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@65e7ca2[cdcr-source_shard1_replica1] main]
[junit4] 2> 1707199 INFO (searcherExecutor-7420-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_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@65e7ca2[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.5.0):C100) Uninverting(_1(6.5.0):C100) Uninverting(_2(6.5.0):C100) Uninverting(_3(6.5.0):C100) Uninverting(_4(6.5.0):C100) Uninverting(_5(6.5.0):C100) Uninverting(_6(6.5.0):C100) Uninverting(_7(6.5.0):C100) Uninverting(_8(6.5.0):C100)))}
[junit4] 2> 1707199 INFO (qtp230876729-19285) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1707199 INFO (qtp230876729-19285) [n:127.0.0.1:55396_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=15
[junit4] 1> Adding 10 docs with commit=true, numDocs=1000
[junit4] 2> 1707204 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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> 1707206 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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> 1707206 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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@10c4327f
[junit4] 2> 1707222 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@27f85fdc[cdcr-source_shard1_replica1] main]
[junit4] 2> 1707222 INFO (qtp230876729-19289) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1707223 INFO (searcherExecutor-7420-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_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@27f85fdc[cdcr-source_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.5.0):C100) Uninverting(_1(6.5.0):C100) Uninverting(_2(6.5.0):C100) Uninverting(_3(6.5.0):C100) Uninverting(_4(6.5.0):C100) Uninverting(_5(6.5.0):C100) Uninverting(_6(6.5.0):C100) Uninverting(_7(6.5.0):C100) Uninverting(_8(6.5.0):C100) Uninverting(_9(6.5.0):C100)))}
[junit4] 2> 1707223 INFO (qtp230876729-19289) [n:127.0.0.1:55396_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=17
[junit4] 2> 1707227 INFO (qtp230876729-19287) [n:127.0.0.1:55396_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=/select params={q=*:*&_stateVer_=cdcr-source:3&wt=javabin&version=2} hits=1000 status=0 QTime=3
[junit4] 2> 1707239 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[48351F47AE662088]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1707240 INFO (TEST-CdcrBootstrapTest.testBootstrapWithSourceCluster-seed#[48351F47AE662088]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:61550/solr ready
[junit4] 2> 1707242 INFO (qtp827698803-19244) [n:127.0.0.1:44270_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=cdcr-target&name=cdcr-target&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 1707248 INFO (OverseerThreadFactory-7409-thread-1-processing-n:127.0.0.1:44270_solr) [n:127.0.0.1:44270_solr ] o.a.s.c.CreateCollectionCmd Create collection cdcr-target
[junit4] 2> 1707356 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=cdcr-target&newCollection=true&name=cdcr-target_shard1_replica1&action=CREATE&numShards=1&collection=cdcr-target&shard=shard1&wt=javabin&version=2
[junit4] 2> 1707463 INFO (zkCallback-3511-thread-1-processing-n:127.0.0.1:44270_solr) [n:127.0.0.1:44270_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> 1708373 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.5.0
[junit4] 2> 1708378 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_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> 1708381 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.s.IndexSchema [cdcr-target_shard1_replica1] Schema name=minimal
[junit4] 2> 1708383 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 1708384 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.s.ManagedIndexSchema Created and persisted managed schema znode at /configs/cdcr-target/managed-schema
[junit4] 2> 1708389 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.s.ManagedIndexSchemaFactory After upgrading to managed schema in ZooKeeper, renamed the non-managed schema /configs/cdcr-target/schema.xml to /configs/cdcr-target/schema.xml.bak
[junit4] 2> 1708390 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.CoreContainer Creating SolrCore 'cdcr-target_shard1_replica1' using configuration from collection cdcr-target
[junit4] 2> 1708390 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.SolrCore [[cdcr-target_shard1_replica1] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.CdcrBootstrapTest_48351F47AE662088-001/cdcr-target-001/node1/cdcr-target_shard1_replica1], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.CdcrBootstrapTest_48351F47AE662088-001/cdcr-target-001/node1/./cdcr-target_shard1_replica1/data/]
[junit4] 2> 1708444 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.CdcrUpdateLog
[junit4] 2> 1708445 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1708445 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1708445 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1708446 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@12336a68[cdcr-target_shard1_replica1] main]
[junit4] 2> 1708449 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/cdcr-target
[junit4] 2> 1708449 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/cdcr-target
[junit4] 2> 1708449 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/cdcr-target/managed-schema
[junit4] 2> 1708450 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Current schema version 0 is already the latest
[junit4] 2> 1708450 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1708455 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.h.CdcrBufferStateManager Created znode /collections/cdcr-target/cdcr/state/buffer
[junit4] 2> 1708458 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.h.CdcrProcessStateManager Created znode /collections/cdcr-target/cdcr/state/process
[junit4] 2> 1708460 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1561231923115720704
[junit4] 2> 1708460 INFO (searcherExecutor-7426-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.SolrCore [cdcr-target_shard1_replica1] Registered new searcher Searcher@12336a68[cdcr-target_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1708469 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1708469 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1708469 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:44270/solr/cdcr-target_shard1_replica1/
[junit4] 2> 1708470 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1708470 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.SyncStrategy http://127.0.0.1:44270/solr/cdcr-target_shard1_replica1/ has no replicas
[junit4] 2> 1708470 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 1708476 INFO (zkCallback-3511-thread-3-processing-n:127.0.0.1:44270_solr) [n:127.0.0.1:44270_solr ] o.a.s.h.CdcrLeaderStateManager Received new leader state @ cdcr-target:shard1
[junit4] 2> 1708479 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:44270/solr/cdcr-target_shard1_replica1/ shard1
[junit4] 2> 1708585 INFO (zkCallback-3511-thread-2-processing-n:127.0.0.1:44270_solr) [n:127.0.0.1:44270_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> 1708631 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1708634 INFO (qtp827698803-19248) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 x:cdcr-target_shard1_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=cdcr-target&newCollection=true&name=cdcr-target_shard1_replica1&action=CREATE&numShards=1&collection=cdcr-target&shard=shard1&wt=javabin&version=2} status=0 QTime=1279
[junit4] 2> 1708641 INFO (qtp827698803-19244) [n:127.0.0.1:44270_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> 1708742 INFO (zkCallback-3511-thread-1-processing-n:127.0.0.1:44270_solr) [n:127.0.0.1:44270_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> 1709250 INFO (OverseerCollectionConfigSetProcessor-97576994852765699-127.0.0.1:44270_solr-n_0000000000) [n:127.0.0.1:44270_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> 1709642 INFO (qtp827698803-19244) [n:127.0.0.1:44270_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=cdcr-target&name=cdcr-target&action=CREATE&numShards=1&wt=javabin&version=2} status=0 QTime=2401
[junit4] 2> 1709650 INFO (qtp827698803-19249) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.S.Request [cdcr-target_shard1_replica1] webapp=/solr path=/cdcr params={qt=/cdcr&_stateVer_=cdcr-target:3&action=start&wt=javabin&version=2} status=0 QTime=3
[junit4] 2> 1709651 INFO (zkCallback-3511-thread-1-processing-n:127.0.0.1:44270_solr) [n:127.0.0.1:44270_solr ] o.a.s.h.CdcrProcessStateManager The CDCR process state has changed: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/cdcr-target/cdcr/state/process @ cdcr-target:shard1
[junit4] 2> 1709651 INFO (zkCallback-3511-thread-1-processing-n:127.0.0.1:44270_solr) [n:127.0.0.1:44270_solr ] o.a.s.h.CdcrProcessStateManager Received new CDCR process state from watcher: STARTED @ cdcr-target:shard1
[junit4] 2> 1709656 INFO (qtp230876729-19290) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1709657 INFO (qtp230876729-19290) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:61550/solr ready
[junit4] 2> 1709667 INFO (qtp827698803-19251) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.CdcrRequestHandler Found maxVersionFromRecent 0 maxVersionFromIndex 0
[junit4] 2> 1709668 INFO (qtp827698803-19251) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.S.Request [cdcr-target_shard1_replica1] webapp=/solr path=/cdcr params={action=SHARDCHECKPOINT&wt=javabin&version=2} status=0 QTime=1
[junit4] 2> 1709674 INFO (qtp827698803-19250) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.S.Request [cdcr-target_shard1_replica1] webapp=/solr path=/cdcr params={_stateVer_=cdcr-target:3&action=COLLECTIONCHECKPOINT&wt=javabin&version=2} status=0 QTime=13
[junit4] 2> 1709677 INFO (qtp230876729-19290) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.h.CdcrReplicatorManager Create new update log reader for target cdcr-target with checkpoint -1 @ cdcr-source:shard1
[junit4] 2> 1709678 INFO (qtp230876729-19290) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.h.CdcrReplicatorManager Attempting to bootstrap target collection: cdcr-target, shard: shard1
[junit4] 2> 1709686 INFO (qtp230876729-19290) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.h.CdcrReplicatorManager Submitting bootstrap task to executor
[junit4] 2> 1709688 INFO (cdcr-bootstrap-status-3535-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.h.CdcrReplicatorManager Attempting to bootstrap target collection: cdcr-target shard: shard1 leader: http://127.0.0.1:44270/solr/cdcr-target_shard1_replica1/
[junit4] 2> 1709701 INFO (zkCallback-3523-thread-3-processing-n:127.0.0.1:55396_solr) [n:127.0.0.1:55396_solr ] o.a.s.h.CdcrProcessStateManager The CDCR process state has changed: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/cdcr-source/cdcr/state/process @ cdcr-source:shard1
[junit4] 2> 1709702 INFO (zkCallback-3523-thread-3-processing-n:127.0.0.1:55396_solr) [n:127.0.0.1:55396_solr ] o.a.s.h.CdcrProcessStateManager Received new CDCR process state from watcher: STARTED @ cdcr-source:shard1
[junit4] 2> 1709702 INFO (qtp827698803-19247) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.S.Request [cdcr-target_shard1_replica1] webapp=/solr path=/cdcr params={qt=/cdcr&masterUrl=http://127.0.0.1:55396/solr/cdcr-source_shard1_replica1/&action=BOOTSTRAP&wt=javabin&version=2} status=0 QTime=1
[junit4] 2> 1709705 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 1709707 INFO (qtp230876729-19291) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1709707 INFO (qtp230876729-19291) [n:127.0.0.1:55396_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@10c4327f
[junit4] 2> 1709710 INFO (qtp230876729-19291) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@63a456f9[cdcr-source_shard1_replica1] realtime]
[junit4] 2> 1709710 INFO (qtp230876729-19291) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1709710 INFO (qtp230876729-19291) [n:127.0.0.1:55396_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={waitSearcher=true&openSearcher=false&commit=true&softCommit=false&commit_end_point=true&wt=javabin&version=2} status=0 QTime=4
[junit4] 2> 1709712 INFO (qtp230876729-19292) [n:127.0.0.1:55396_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=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1709712 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.IndexFetcher Master's generation: 12
[junit4] 2> 1709712 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.IndexFetcher Master's version: 1488906788276
[junit4] 2> 1709712 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 1709712 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.IndexFetcher Slave's version: 0
[junit4] 2> 1709712 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.IndexFetcher Starting replication process
[junit4] 2> 1709713 INFO (qtp230876729-19290) [n:127.0.0.1:55396_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=/cdcr params={qt=/cdcr&_stateVer_=cdcr-source:3&action=start&wt=javabin&version=2} status=0 QTime=60
[junit4] 2> 1709718 INFO (qtp230876729-19292) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.h.ReplicationHandler Adding tlog files to list: [{size=4649, name=tlog.0000000000000000000.1561231921587945472}, {size=4770, name=tlog.0000000000000000001.1561231921614159872}, {size=4770, name=tlog.0000000000000000002.1561231921636179968}, {size=4770, name=tlog.0000000000000000003.1561231921657151488}, {size=4770, name=tlog.0000000000000000004.1561231921680220160}, {size=4770, name=tlog.0000000000000000005.1561231921701191680}, {size=4770, name=tlog.0000000000000000006.1561231921722163200}, {size=4770, name=tlog.0000000000000000007.1561231921749426176}, {size=4770, name=tlog.0000000000000000008.1561231921772494848}, {size=4770, name=tlog.0000000000000000009.1561231921795563520}]
[junit4] 2> 1709718 INFO (qtp230876729-19292) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&wt=javabin&version=2&command=filelist} status=0 QTime=4
[junit4] 2> 1709718 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.IndexFetcher Number of files in latest index in master: 11
[junit4] 2> 1709718 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.IndexFetcher Number of tlog files in master: 10
[junit4] 2> 1709719 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1709720 INFO (qtp230876729-19292) [n:127.0.0.1:55396_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=/cdcr params={qt=/cdcr&_stateVer_=cdcr-source:3&action=queues&wt=javabin&version=2} status=0 QTime=0
[junit4] 1> Cdcr queue response: {responseHeader={status=0,QTime=0},queues={127.0.0.1:61550/solr={cdcr-target={queueSize=1010,lastTimestamp=}}},tlogTotalSize=47579,tlogTotalCount=10,updateLogSynchronizer=stopped}
[junit4] 2> 1709722 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.IndexFetcher Starting download (fullCopy=false) to MockDirectoryWrapper(RAMDirectory@6bf09622 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@41ec120f)
[junit4] 2> 1709723 INFO (qtp827698803-19247) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.u.p.DistributedUpdateProcessor Ignoring commit while not ACTIVE - state: BUFFERING replay: false
[junit4] 2> 1709723 INFO (qtp827698803-19247) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.S.Request [cdcr-target_shard1_replica1] webapp=/solr path=/update params={_stateVer_=cdcr-target:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 1709724 INFO (qtp230876729-19292) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&file=_a.fnm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709729 INFO (qtp230876729-19292) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&file=_a.nvm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709731 INFO (qtp230876729-19292) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&file=_a.pos&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709734 INFO (qtp230876729-19291) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&file=_a.fdt&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709737 INFO (qtp230876729-19285) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&file=_a.doc&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709739 INFO (qtp230876729-19285) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&file=_a.si&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709741 INFO (qtp230876729-19285) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&file=_a.tim&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709744 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&file=_a.tip&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709746 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&file=_a.fdx&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709748 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&file=_a.nvd&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709751 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&file=segments_c&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709751 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.IndexFetcher Starting download of tlog files from master: [{size=4649, name=tlog.0000000000000000000.1561231921587945472}, {size=4770, name=tlog.0000000000000000001.1561231921614159872}, {size=4770, name=tlog.0000000000000000002.1561231921636179968}, {size=4770, name=tlog.0000000000000000003.1561231921657151488}, {size=4770, name=tlog.0000000000000000004.1561231921680220160}, {size=4770, name=tlog.0000000000000000005.1561231921701191680}, {size=4770, name=tlog.0000000000000000006.1561231921722163200}, {size=4770, name=tlog.0000000000000000007.1561231921749426176}, {size=4770, name=tlog.0000000000000000008.1561231921772494848}, {size=4770, name=tlog.0000000000000000009.1561231921795563520}]
[junit4] 2> 1709754 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&checksum=true&tlogFile=tlog.0000000000000000000.1561231921587945472&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709757 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&checksum=true&tlogFile=tlog.0000000000000000001.1561231921614159872&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709759 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&checksum=true&tlogFile=tlog.0000000000000000002.1561231921636179968&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709762 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&checksum=true&tlogFile=tlog.0000000000000000003.1561231921657151488&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709764 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&checksum=true&tlogFile=tlog.0000000000000000004.1561231921680220160&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709766 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&checksum=true&tlogFile=tlog.0000000000000000005.1561231921701191680&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709769 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&checksum=true&tlogFile=tlog.0000000000000000006.1561231921722163200&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709771 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&checksum=true&tlogFile=tlog.0000000000000000007.1561231921749426176&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709775 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&checksum=true&tlogFile=tlog.0000000000000000008.1561231921772494848&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709777 INFO (qtp230876729-19288) [n:127.0.0.1:55396_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=/replication params={generation=12&qt=/replication&checksum=true&tlogFile=tlog.0000000000000000009.1561231921795563520&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1709778 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.IndexFetcher Total time taken for download (fullCopy=false,bytesDownloaded=92635) : 0 secs (null bytes/sec) to MockDirectoryWrapper(RAMDirectory@6bf09622 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@41ec120f)
[junit4] 2> 1709785 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1709785 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.IndexFetcher Reloading SolrCore cdcr-target_shard1_replica1
[junit4] 2> 1709786 INFO (qtp827698803-19247) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@4b87022c[cdcr-target_shard1_replica1] main]
[junit4] 2> 1709786 INFO (qtp827698803-19247) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.S.Request [cdcr-target_shard1_replica1] webapp=/solr path=/cdcr params={qt=/cdcr&action=BOOTSTRAP_STATUS&wt=javabin&version=2} status=0 QTime=62
[junit4] 2> 1709787 INFO (cdcr-bootstrap-status-3535-thread-1-processing-n:127.0.0.1:55396_solr x:cdcr-source_shard1_replica1 s:shard1 c:cdcr-source r:core_node1) [n:127.0.0.1:55396_solr c:cdcr-source s:shard1 r:core_node1 x:cdcr-source_shard1_replica1] o.a.s.h.CdcrReplicatorManager CDCR bootstrap running for 1 seconds, sleeping for 2000 ms
[junit4] 2> 1709788 INFO (searcherExecutor-7426-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.SolrCore [cdcr-target_shard1_replica1] Registered new searcher Searcher@4b87022c[cdcr-target_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.5.0):C1000)))}
[junit4] 2> 1709788 INFO (qtp827698803-19249) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.S.Request [cdcr-target_shard1_replica1] webapp=/solr path=/select params={q=*:*&_stateVer_=cdcr-target:3&wt=javabin&version=2} hits=1000 status=0 QTime=63
[junit4] 2> 1709796 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.5.0
[junit4] 2> 1709801 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.s.IndexSchema [cdcr-target_shard1_replica1] Schema name=minimal
[junit4] 2> 1709803 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 1709805 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.CoreContainer Reloading SolrCore 'cdcr-target_shard1_replica1' using configuration from collection cdcr-target
[junit4] 2> 1709805 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.SolrCore [[cdcr-target_shard1_replica1] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.CdcrBootstrapTest_48351F47AE662088-001/cdcr-target-001/node1/cdcr-target_shard1_replica1], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.cloud.CdcrBootstrapTest_48351F47AE662088-001/cdcr-target-001/node1/./cdcr-target_shard1_replica1/data/]
[junit4] 2> 1709846 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1709847 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1709848 INFO (qtp827698803-19246) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.S.Request [cdcr-target_shard1_replica1] webapp=/solr path=/cdcr params={qt=/cdcr&action=CANCEL_BOOTSTRAP&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 1709854 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@5c240ce0[cdcr-target_shard1_replica1] main]
[junit4] 2> 1709856 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/cdcr-target
[junit4] 2> 1709857 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/cdcr-target
[junit4] 2> 1709857 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/cdcr-target/managed-schema
[junit4] 2> 1709857 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Current schema version 0 is already the latest
[junit4] 2> 1709858 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1709863 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1709873 INFO (searcherExecutor-7438-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.SolrCore [cdcr-target_shard1_replica1] Registered new searcher Searcher@5c240ce0[cdcr-target_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.5.0):C1000)))}
[junit4] 2> 1709873 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@66f2bd[cdcr-target_shard1_replica1] main]
[junit4] 2> 1709873 INFO (Thread-5704) [n:127.0.0.1:44270_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@613f491a
[junit4] 2> 1709874 INFO (Thread-5704) [n:127.0.0.1:44270_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> 1709875 INFO (searcherExecutor-7438-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.c.SolrCore [cdcr-target_shard1_replica1] Registered new searcher Searcher@66f2bd[cdcr-target_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a(6.5.0):C1000)))}
[junit4] 2> 1709875 INFO (Thread-5704) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.cdcr-target.shard1.replica1
[junit4] 2> 1709876 INFO (recoveryExecutor-3509-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.CdcrRequestHandler No replay needed.
[junit4] 2> 1709878 ERROR (updateExecutor-3508-thread-1-processing-n:127.0.0.1:44270_solr x:cdcr-target_shard1_replica1 s:shard1 c:cdcr-target r:core_node1) [n:127.0.0.1:44270_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.h.CdcrRequestHandler Bootstrap operation failed
[junit4] 2> java.util.concurrent.ExecutionException: java.lang.AssertionError
[junit4] 2> at java.util.concurrent.FutureTask.report(FutureTask.java:122)
[junit4] 2> at java.util.concurrent.FutureTask.get(FutureTask.java:192)
[junit4] 2> at org.apache.solr.handler.CdcrRequestHandler.lambda$handleBootstrapAction$0(CdcrRequestHandler.java:643)
[junit4] 2> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java: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> Caused by: java.lang.AssertionError
[junit4] 2> at org.apache.solr.handler.Cd
[...truncated too long message...]
erseer/collection-queue-work
[junit4] 2> 5 /solr/overseer/queue
[junit4] 2> 3 /solr/overseer/queue-work
[junit4] 2> 2 /solr/live_nodes
[junit4] 2> 2 /solr/collections
[junit4] 2>
[junit4] 2> 1857508 INFO (jetty-closer-3581-thread-1) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@62818f82{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1857509 INFO (jetty-closer-3581-thread-1) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=194718635
[junit4] 2> 1857512 INFO (coreCloseExecutor-7561-thread-1) [n:127.0.0.1:50420_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@10616ffc
[junit4] 2> 1857512 INFO (coreCloseExecutor-7561-thread-1) [n:127.0.0.1:50420_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> 1857514 INFO (coreCloseExecutor-7561-thread-1) [n:127.0.0.1:50420_solr c:cdcr-target s:shard1 r:core_node1 x:cdcr-target_shard1_replica1] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.cdcr-target.shard1.replica1
[junit4] 2> 1857514 INFO (zkCallback-3587-thread-3-processing-n:127.0.0.1:50420_solr) [n:127.0.0.1:50420_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> 1857516 INFO (jetty-closer-3581-thread-1) [ ] o.a.s.c.Overseer Overseer (id=97577004109201411-127.0.0.1:50420_solr-n_0000000000) closing
[junit4] 2> 1857516 INFO (OverseerStateUpdate-97577004109201411-127.0.0.1:50420_solr-n_0000000000) [n:127.0.0.1:50420_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:50420_solr
[junit4] 2> 1857518 WARN (zkCallback-3587-thread-3-processing-n:127.0.0.1:50420_solr) [n:127.0.0.1:50420_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 1857520 INFO (jetty-closer-3581-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.node
[junit4] 2> 1857520 INFO (jetty-closer-3581-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@2138fe70{/solr,null,UNAVAILABLE}
[junit4] 2> 1857524 INFO (TEST-CdcrBootstrapTest.testBootstrapWithContinousIndexingOnSourceCluster-seed#[48351F47AE662088]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:42291 42291
[junit4] 2> 1857541 INFO (Thread-5741) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:42291 42291
[junit4] 2> 1857543 WARN (Thread-5741) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/configs/cdcr-target/managed-schema
[junit4] 2> 3 /solr/aliases.json
[junit4] 2> 3 /solr/clusterprops.json
[junit4] 2> 3 /solr/collections/cdcr-target/leaders/shard1/leader
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 4 /solr/collections/cdcr-target/cdcr/state/process
[junit4] 2> 3 /solr/collections/cdcr-target/cdcr/state/buffer
[junit4] 2> 3 /solr/clusterstate.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 11 /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> 1857543 INFO (TEST-CdcrBootstrapTest.testBootstrapWithContinousIndexingOnSourceCluster-seed#[48351F47AE662088]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testBootstrapWithContinousIndexingOnSourceCluster
[junit4] 2> 1857544 INFO (SUITE-CdcrBootstrapTest-seed#[48351F47AE662088]-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.CdcrBootstrapTest_48351F47AE662088-001
[junit4] 2> Mar 07, 2017 5:15:36 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 4 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarity(queryNorm=false,coord=crazy): {}, locale=es-CU, timezone=Europe/Skopje
[junit4] 2> NOTE: SunOS 5.11 amd64/Oracle Corporation 1.8.0_121 (64-bit)/cpus=3,threads=1,free=153873864,total=492830720
[junit4] 2> NOTE: All tests run in this JVM: [BlobRepositoryCloudTest, PolyFieldTest, LeaderInitiatedRecoveryOnCommitTest, UniqFieldsUpdateProcessorFactoryTest, TestCollationFieldDocValues, TestCustomStream, PeerSyncReplicationTest, TestEmbeddedSolrServerConstructors, TestRequestForwarding, TestRTimerTree, TestSolrFieldCacheMBean, TestHdfsCloudBackupRestore, TestClassNameShortening, TestSystemCollAutoCreate, TestDeleteCollectionOnDownNodes, TestTestInjection, TestGroupingSearch, TestFieldCacheSortRandom, SuggesterFSTTest, DateFieldTest, RequiredFieldsTest, XmlUpdateRequestHandlerTest, VMParamsZkACLAndCredentialsProvidersTest, TestRandomDVFaceting, TlogReplayBufferedWhileIndexingTest, TestStressRecovery, EnumFieldTest, TestMinMaxOnMultiValuedField, TestJsonFacetRefinement, DocValuesMultiTest, TestSolr4Spatial2, BitVectorTest, TestBlobHandler, TestBlendedInfixSuggestions, TestDocumentBuilder, HdfsRecoveryZkTest, TestPerFieldSimilarityClassic, DOMUtilTest, TestPostingsSolrHighlighter, JavabinLoaderTest, TestSolrDeletionPolicy1, LeaderFailoverAfterPartitionTest, SaslZkACLProviderTest, TestCloudInspectUtil, TestRawTransformer, TestXIncludeConfig, TestComplexPhraseQParserPlugin, TestFieldCacheWithThreads, TestRandomCollapseQParserPlugin, BlockJoinFacetDistribTest, TestLeaderElectionZkExpiry, TestSQLHandler, TestJsonRequest, TestPhraseSuggestions, HighlighterTest, TestConfigSets, DirectoryFactoryTest, TestSolrCloudWithSecureImpersonation, ResponseLogComponentTest, TestLocalFSCloudBackupRestore, UpdateLogTest, DistribDocExpirationUpdateProcessorTest, HardAutoCommitTest, PreAnalyzedFieldManagedSchemaCloudTest, TestUnifiedSolrHighlighter, ZkStateWriterTest, MetricUtilsTest, TestDefaultSearchFieldResource, DocExpirationUpdateProcessorFactoryTest, DirectSolrConnectionTest, TestPushWriter, DataDrivenBlockJoinTest, DeleteReplicaTest, CdcrReplicationDistributedZkTest, TestMacroExpander, FullHLLTest, TestExactStatsCache, TestMiniSolrCloudClusterSSL, MultiThreadedOCPTest, TestSolrIndexConfig, OverseerModifyCollectionTest, TestManagedResource, TestSchemalessBufferedUpdates, RollingRestartTest, BlockCacheTest, UUIDUpdateProcessorFallbackTest, TestDistributedSearch, TestFieldTypeResource, TestSimpleQParserPlugin, DistributedFacetPivotLongTailTest, TestConfigSetsAPI, TestExtendedDismaxParser, TestConfigSetImmutable, SolrCloudExampleTest, ShardRoutingTest, DisMaxRequestHandlerTest, DeleteLastCustomShardedReplicaTest, TestXmlQParser, QueryElevationComponentTest, TestCollationField, ZkControllerTest, TestNamedUpdateProcessors, TestSolrCoreSnapshots, DistributedFacetExistsSmallTest, SystemInfoHandlerTest, AnalysisErrorHandlingTest, OverseerTest, HttpSolrCallGetCoreTest, DistributedSpellCheckComponentTest, ZkCLITest, StandardRequestHandlerTest, TestIBSimilarityFactory, TestManagedSynonymFilterFactory, TestMissingGroups, TestTolerantUpdateProcessorCloud, TestHighlightDedupGrouping, TestSolrCloudWithDelegationTokens, PathHierarchyTokenizerFactoryTest, QueryEqualityTest, BadComponentTest, SimpleCollectionCreateDeleteTest, JSONWriterTest, TestCollapseQParserPlugin, ConnectionManagerTest, TestHdfsBackupRestoreCore, TestDownShardTolerantSearch, TestLazyCores, TestPerFieldSimilarity, TestWordDelimiterFilterFactory, SolrJmxReporterTest, TestElisionMultitermQuery, DistributedMLTComponentTest, TestStressVersions, TestClusterProperties, DistributedQueryElevationComponentTest, ClassificationUpdateProcessorTest, TestBinaryResponseWriter, TermsComponentTest, DocValuesTest, TestLRUCache, TestExportWriter, TestSolrXml, TestRestManager, TestDistribIDF, AnalysisAfterCoreReloadTest, CustomCollectionTest, MergeStrategyTest, StatelessScriptUpdateProcessorFactoryTest, ZkNodePropsTest, SolrRequestParserTest, SolrIndexMetricsTest, TestAuthenticationFramework, TestInitQParser, TestCharFilters, HdfsSyncSliceTest, TestBulkSchemaConcurrent, MigrateRouteKeyTest, TestReRankQParserPlugin, TestConfigsApi, DistributedQueryComponentCustomSortTest, TestFastLRUCache, JsonValidatorTest, CoreMergeIndexesAdminHandlerTest, TestHashPartitioner, HdfsLockFactoryTest, CoreAdminCreateDiscoverTest, DeleteStatusTest, HdfsWriteToMultipleCollectionsTest, JSONWriterTest, OpenCloseCoreStressTest, RecoveryZkTest, TestReplicationHandler, AutoCommitTest, TestFaceting, TestRecovery, TestStressReorder, TestCoreContainer, SimpleFacetsTest, StatsComponentTest, PeerSyncTest, DirectUpdateHandlerTest, SoftAutoCommitTest, TestPartialUpdateDeduplication, PingRequestHandlerTest, SOLR749Test, TestQuerySenderListener, UpdateParamsTest, AlternateDirectoryTest, CopyFieldTest, SolrIndexConfigTest, MultiTermTest, SampleTest, TestDocSet, TestBinaryField, TestSearchPerf, NumericFieldsTest, OutputWriterTest, TestSolrCoreProperties, TestLuceneMatchVersion, SpellPossibilityIteratorTest, TestCodecSupport, SynonymTokenizerTest, EchoParamsTest, TestSweetSpotSimilarityFactory, TestBM25SimilarityFactory, TimeZoneUtilsTest, TestFastOutputStream, OpenExchangeRatesOrgProviderTest, PluginInfoTest, ChaosMonkeyNothingIsSafeTest, BaseCdcrDistributedZkTest, CdcrBootstrapTest]
[junit4] Completed [497/697 (1!)] on J0 in 155.34s, 3 tests, 1 failure <<< FAILURES!
[...truncated 63340 lines...]