You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2016/09/24 21:34:24 UTC
[JENKINS] Lucene-Solr-6.x-Windows (64bit/jdk1.8.0_102) - Build #
473 - Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Windows/473/
Java: 64bit/jdk1.8.0_102 -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: org.apache.solr.cloud.RecoveryZkTest.test
Error Message:
Captured an uncaught exception in thread: Thread[id=10444, name=updateExecutor-1725-thread-2, state=RUNNABLE, group=TGRP-RecoveryZkTest]
Stack Trace:
com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=10444, name=updateExecutor-1725-thread-2, state=RUNNABLE, group=TGRP-RecoveryZkTest]
at __randomizedtesting.SeedInfo.seed([68A817BFFB88BCDF:E0FC28655574D127]:0)
Caused by: org.apache.solr.common.SolrException: Replica: http://127.0.0.1:60276/collection1/ should have been marked under leader initiated recovery in ZkController but wasn't.
at __randomizedtesting.SeedInfo.seed([68A817BFFB88BCDF]:0)
at org.apache.solr.cloud.LeaderInitiatedRecoveryThread.run(LeaderInitiatedRecoveryThread.java:88)
at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 11496 lines...]
[junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4] 2> Creating dataDir: C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\init-core-data-001
[junit4] 2> 1418066 INFO (SUITE-RecoveryZkTest-seed#[68A817BFFB88BCDF]-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> 1418066 INFO (SUITE-RecoveryZkTest-seed#[68A817BFFB88BCDF]-worker) [ ] o.a.s.BaseDistributedSearchTestCase Setting hostContext system property: /
[junit4] 2> 1418067 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 1418068 INFO (Thread-2366) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1418068 INFO (Thread-2366) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 1418169 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.ZkTestServer start zk server on port:60239
[junit4] 2> 1418173 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1418178 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1418184 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 1418186 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\schema15.xml to /configs/conf1/schema.xml
[junit4] 2> 1418189 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 1418191 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 1418193 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 1418195 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4] 2> 1418197 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\enumsConfig.xml to /configs/conf1/enumsConfig.xml
[junit4] 2> 1418199 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 1418201 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 1418202 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 1418205 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractZkTestCase put C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\core\src\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 1418207 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x1575dec1b600001, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 1418650 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\control-001\cores\collection1
[junit4] 2> 1418653 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1418654 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@801e89a{/,null,AVAILABLE}
[junit4] 2> 1418658 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.ServerConnector Started ServerConnector@4c9177{HTTP/1.1,[http/1.1]}{127.0.0.1:60246}
[junit4] 2> 1418658 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.Server Started @1424230ms
[junit4] 2> 1418658 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\tempDir-001/control/data, hostContext=/, hostPort=60246, coreRootDirectory=C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\control-001\cores}
[junit4] 2> 1418661 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1418662 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1418662 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\control-001\solr.xml
[junit4] 2> 1418674 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1418675 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:60239/solr
[junit4] 2> 1418677 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1418681 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60246_ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1418696 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60246_ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 1418698 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60246_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (0)
[junit4] 2> 1418704 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60246_ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:60246_
[junit4] 2> 1418705 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60246_ ] o.a.s.c.Overseer Overseer (id=96649185664696324-127.0.0.1:60246_-n_0000000000) starting
[junit4] 2> 1418715 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60246_ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60246_
[junit4] 2> 1418717 INFO (OverseerStateUpdate-96649185664696324-127.0.0.1:60246_-n_0000000000) [n:127.0.0.1:60246_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1418717 INFO (zkCallback-1718-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (1)
[junit4] 2> 1418726 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60246_ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\control-001\cores
[junit4] 2> 1418726 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60246_ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1418728 INFO (OverseerStateUpdate-96649185664696324-127.0.0.1:60246_-n_0000000000) [n:127.0.0.1:60246_ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 1419733 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection x:collection1] o.a.s.c.Config loaded config solrconfig.xml with version 0
[junit4] 2> 1419747 WARN (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection x:collection1] o.a.s.c.Config Beginning with Solr 5.5, <mergePolicy> is deprecated, use <mergePolicyFactory> instead.
[junit4] 2> 1419748 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1419757 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection x:collection1] o.a.s.c.SolrConfig Loaded SolrConfig: solrconfig.xml
[junit4] 2> 1419763 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1419830 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection x:collection1] o.a.s.s.IndexSchema [collection1] default search field in schema is text. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 1419831 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection x:collection1] o.a.s.s.IndexSchema [collection1] unique key field: id
[junit4] 2> 1419854 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection control_collection
[junit4] 2> 1419854 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\control-001\cores\collection1], dataDir=[C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\control-001\cores\collection1\data\]
[junit4] 2> 1419854 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2311d6ad
[junit4] 2> 1419856 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore New index directory detected: old=null new=C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\control-001\cores\collection1\data\index/
[junit4] 2> 1419856 WARN (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Solr index directory 'C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\control-001\cores\collection1\data\index' doesn't exist. Creating new index...
[junit4] 2> 1419856 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=28, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=83.6923828125, floorSegmentMB=0.685546875, forceMergeDeletesPctAllowed=26.134585952057705, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1419857 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1b4de09f lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@1efa40fe),segFN=segments_1,generation=1}
[junit4] 2> 1419857 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy newest commit generation = 1
[junit4] 2> 1419857 WARN (OldIndexDirectoryCleanupThreadForCore-collection1) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.DirectoryFactory C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\control-001\cores\collection1\data\ does not point to a valid data directory; skipping clean-up of old index directories.
[junit4] 2> 1419858 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 1419858 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "dedupe"
[junit4] 2> 1419858 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 1419858 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 1419858 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 1419860 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 1419862 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1419862 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1419863 WARN (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,args = {defaults={a=A,b=B}}}
[junit4] 2> 1419874 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.PluginBag [collection1] Initialized 25 plugins of type requestHandler: [/update, /update/json, /update/csv, /update/json/docs, /config, /schema, /replication, /get, /admin/ping, /admin/segments, /admin/luke, /admin/system, /admin/mbeans, /admin/plugins, /admin/threads, /admin/properties, /admin/logging, /admin/file, /export, /graph, /stream, /sql, /terms, standard, /dump]
[junit4] 2> 1419874 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.RequestHandlers Registered paths: /admin/mbeans,standard,/update/json/docs,/admin/luke,/export,/get,/admin/properties,/update/json,/admin/threads,/dump,/update/csv,/sql,/graph,/admin/segments,/admin/system,/replication,/config,/stream,/schema,/admin/plugins,/admin/logging,/admin/ping,/update,/admin/file,/terms
[junit4] 2> 1419875 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1419875 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1419876 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1419876 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1419876 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=32, maxMergeAtOnceExplicit=15, maxMergedSegmentMB=12.5205078125, floorSegmentMB=0.33203125, forceMergeDeletesPctAllowed=16.747310080744324, segmentsPerTier=46.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.285183366414781
[junit4] 2> 1419877 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@1b4de09f lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@1efa40fe),segFN=segments_1,generation=1}
[junit4] 2> 1419877 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy newest commit generation = 1
[junit4] 2> 1419877 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@5236af92[collection1] main]
[junit4] 2> 1419878 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
[junit4] 2> 1419879 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1419879 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.RestManager Initializing RestManager with initArgs: {}
[junit4] 2> 1419879 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1419880 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage No data found for znode /configs/conf1/_rest_managed.json
[junit4] 2> 1419880 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1419880 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.RestManager Initializing 0 registered ManagedResources
[junit4] 2> 1419880 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1419880 INFO (searcherExecutor-5401-thread-1-processing-n:127.0.0.1:60246_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@5236af92[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1419881 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Looking up max value of version field to seed version buckets
[junit4] 2> 1419881 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.VersionInfo Refreshing highest value of _version_ for 65536 version buckets from index
[junit4] 2> 1419881 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.VersionInfo No terms found for _version_, cannot seed version bucket highest value from index
[junit4] 2> 1419881 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1546386972532015104
[junit4] 2> 1419882 INFO (coreLoadExecutor-5400-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Took 1.0ms to seed version buckets with highest version 1546386972532015104
[junit4] 2> 1419888 INFO (coreZkRegister-5393-thread-1-processing-n:127.0.0.1:60246_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Running the leader process for shard=shard1 and weAreReplacement=false and leaderVoteWait=10000
[junit4] 2> 1419889 INFO (coreZkRegister-5393-thread-1-processing-n:127.0.0.1:60246_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1419889 INFO (coreZkRegister-5393-thread-1-processing-n:127.0.0.1:60246_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1419889 INFO (coreZkRegister-5393-thread-1-processing-n:127.0.0.1:60246_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:60246/collection1/
[junit4] 2> 1419889 INFO (coreZkRegister-5393-thread-1-processing-n:127.0.0.1:60246_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1419889 INFO (coreZkRegister-5393-thread-1-processing-n:127.0.0.1:60246_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy http://127.0.0.1:60246/collection1/ has no replicas
[junit4] 2> 1419893 INFO (coreZkRegister-5393-thread-1-processing-n:127.0.0.1:60246_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContextBase Creating leader registration node /collections/control_collection/leaders/shard1/leader after winning as /collections/control_collection/leader_elect/shard1/election/96649185664696324-core_node1-n_0000000000
[junit4] 2> 1419894 INFO (coreZkRegister-5393-thread-1-processing-n:127.0.0.1:60246_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:60246/collection1/ shard1
[junit4] 2> 1420047 INFO (coreZkRegister-5393-thread-1-processing-n:127.0.0.1:60246_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1420229 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1420229 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 1420231 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1420232 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.ChaosMonkey monkey: init - expire sessions:false cause connection loss:false
[junit4] 2> 1420232 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractFullDistribZkTestBase Creating collection1 with stateFormat=2
[junit4] 2> 1420234 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1420705 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-1-001\cores\collection1
[junit4] 2> 1420708 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 1 in directory C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-1-001
[junit4] 2> 1420708 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1420709 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@34646c76{/,null,AVAILABLE}
[junit4] 2> 1420710 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.ServerConnector Started ServerConnector@43d2dd39{HTTP/1.1,[http/1.1]}{127.0.0.1:60264}
[junit4] 2> 1420710 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.Server Started @1426283ms
[junit4] 2> 1420710 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\tempDir-001/jetty1, solrconfig=solrconfig.xml, hostContext=/, hostPort=60264, coreRootDirectory=C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-1-001\cores}
[junit4] 2> 1420714 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1420715 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1420715 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-1-001\solr.xml
[junit4] 2> 1420738 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1420739 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:60239/solr
[junit4] 2> 1420740 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1420744 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60264_ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1420750 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60264_ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 1420752 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60264_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1420756 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60264_ ] o.a.s.c.ZkController Publish node=127.0.0.1:60264_ as DOWN
[junit4] 2> 1420758 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60264_ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60264_
[junit4] 2> 1420759 INFO (OverseerStateUpdate-96649185664696324-127.0.0.1:60246_-n_0000000000) [n:127.0.0.1:60246_ ] o.a.s.c.o.NodeMutator DownNode state invoked for node: 127.0.0.1:60264_
[junit4] 2> 1420760 INFO (zkCallback-1718-thread-3-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1420760 INFO (zkCallback-1722-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1420761 INFO (zkCallback-1728-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1420778 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60264_ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-1-001\cores
[junit4] 2> 1420779 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60264_ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1420781 INFO (OverseerStateUpdate-96649185664696324-127.0.0.1:60246_-n_0000000000) [n:127.0.0.1:60246_ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 1420887 INFO (zkCallback-1728-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json] for collection [collection1] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1421785 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 x:collection1] o.a.s.c.Config loaded config solrconfig.xml with version 0
[junit4] 2> 1421795 WARN (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 x:collection1] o.a.s.c.Config Beginning with Solr 5.5, <mergePolicy> is deprecated, use <mergePolicyFactory> instead.
[junit4] 2> 1421796 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1421823 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 x:collection1] o.a.s.c.SolrConfig Loaded SolrConfig: solrconfig.xml
[junit4] 2> 1421828 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1421899 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] default search field in schema is text. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 1421900 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] unique key field: id
[junit4] 2> 1421927 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1
[junit4] 2> 1421928 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-1-001\cores\collection1], dataDir=[C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-1-001\cores\collection1\data\]
[junit4] 2> 1421928 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2311d6ad
[junit4] 2> 1421928 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore New index directory detected: old=null new=C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-1-001\cores\collection1\data\index/
[junit4] 2> 1421928 WARN (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Solr index directory 'C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-1-001\cores\collection1\data\index' doesn't exist. Creating new index...
[junit4] 2> 1421929 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=28, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=83.6923828125, floorSegmentMB=0.685546875, forceMergeDeletesPctAllowed=26.134585952057705, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1421929 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@4b0ebc1 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@59f238f4),segFN=segments_1,generation=1}
[junit4] 2> 1421929 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy newest commit generation = 1
[junit4] 2> 1421930 WARN (OldIndexDirectoryCleanupThreadForCore-collection1) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.DirectoryFactory C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-1-001\cores\collection1\data\ does not point to a valid data directory; skipping clean-up of old index directories.
[junit4] 2> 1421931 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 1421931 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "dedupe"
[junit4] 2> 1421931 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 1421932 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 1421932 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 1421932 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 1421932 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1421932 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1421932 WARN (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,args = {defaults={a=A,b=B}}}
[junit4] 2> 1421948 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.PluginBag [collection1] Initialized 25 plugins of type requestHandler: [/update, /update/json, /update/csv, /update/json/docs, /config, /schema, /replication, /get, /admin/ping, /admin/segments, /admin/luke, /admin/system, /admin/mbeans, /admin/plugins, /admin/threads, /admin/properties, /admin/logging, /admin/file, /export, /graph, /stream, /sql, /terms, standard, /dump]
[junit4] 2> 1421948 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.RequestHandlers Registered paths: /admin/mbeans,standard,/update/json/docs,/admin/luke,/export,/get,/admin/properties,/update/json,/admin/threads,/dump,/update/csv,/sql,/graph,/admin/segments,/admin/system,/replication,/config,/stream,/schema,/admin/plugins,/admin/logging,/admin/ping,/update,/admin/file,/terms
[junit4] 2> 1421950 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1421950 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1421952 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1421952 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1421953 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=32, maxMergeAtOnceExplicit=15, maxMergedSegmentMB=12.5205078125, floorSegmentMB=0.33203125, forceMergeDeletesPctAllowed=16.747310080744324, segmentsPerTier=46.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.285183366414781
[junit4] 2> 1421953 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@4b0ebc1 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@59f238f4),segFN=segments_1,generation=1}
[junit4] 2> 1421953 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrDeletionPolicy newest commit generation = 1
[junit4] 2> 1421953 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@7f54284c[collection1] main]
[junit4] 2> 1421955 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
[junit4] 2> 1421955 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1421955 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.r.RestManager Initializing RestManager with initArgs: {}
[junit4] 2> 1421955 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1421956 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage No data found for znode /configs/conf1/_rest_managed.json
[junit4] 2> 1421956 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1421956 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.r.RestManager Initializing 0 registered ManagedResources
[junit4] 2> 1421956 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1421957 INFO (searcherExecutor-5412-thread-1-processing-n:127.0.0.1:60264_ x:collection1 s:shard1 c:collection1 r:core_node1) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@7f54284c[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1421957 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Looking up max value of version field to seed version buckets
[junit4] 2> 1421957 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.VersionInfo Refreshing highest value of _version_ for 65536 version buckets from index
[junit4] 2> 1421957 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.VersionInfo No terms found for _version_, cannot seed version bucket highest value from index
[junit4] 2> 1421957 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1546386974708858880
[junit4] 2> 1421959 INFO (coreLoadExecutor-5411-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Took 2.0ms to seed version buckets with highest version 1546386974708858880
[junit4] 2> 1421966 INFO (coreZkRegister-5406-thread-1-processing-n:127.0.0.1:60264_ x:collection1 s:shard1 c:collection1 r:core_node1) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Running the leader process for shard=shard1 and weAreReplacement=false and leaderVoteWait=10000
[junit4] 2> 1421968 INFO (coreZkRegister-5406-thread-1-processing-n:127.0.0.1:60264_ x:collection1 s:shard1 c:collection1 r:core_node1) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1421968 INFO (coreZkRegister-5406-thread-1-processing-n:127.0.0.1:60264_ x:collection1 s:shard1 c:collection1 r:core_node1) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1421968 INFO (coreZkRegister-5406-thread-1-processing-n:127.0.0.1:60264_ x:collection1 s:shard1 c:collection1 r:core_node1) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:60264/collection1/
[junit4] 2> 1421968 INFO (coreZkRegister-5406-thread-1-processing-n:127.0.0.1:60264_ x:collection1 s:shard1 c:collection1 r:core_node1) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1421968 INFO (coreZkRegister-5406-thread-1-processing-n:127.0.0.1:60264_ x:collection1 s:shard1 c:collection1 r:core_node1) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy http://127.0.0.1:60264/collection1/ has no replicas
[junit4] 2> 1421972 INFO (coreZkRegister-5406-thread-1-processing-n:127.0.0.1:60264_ x:collection1 s:shard1 c:collection1 r:core_node1) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContextBase Creating leader registration node /collections/collection1/leaders/shard1/leader after winning as /collections/collection1/leader_elect/shard1/election/96649185664696329-core_node1-n_0000000000
[junit4] 2> 1421975 INFO (coreZkRegister-5406-thread-1-processing-n:127.0.0.1:60264_ x:collection1 s:shard1 c:collection1 r:core_node1) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:60264/collection1/ shard1
[junit4] 2> 1422079 INFO (zkCallback-1728-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json] for collection [collection1] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1422128 INFO (coreZkRegister-5406-thread-1-processing-n:127.0.0.1:60264_ x:collection1 s:shard1 c:collection1 r:core_node1) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1422233 INFO (zkCallback-1728-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json] for collection [collection1] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1422745 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-2-001\cores\collection1
[junit4] 2> 1422748 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 2 in directory C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-2-001
[junit4] 2> 1422749 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1422750 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1a47573d{/,null,AVAILABLE}
[junit4] 2> 1422751 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.ServerConnector Started ServerConnector@b47397a{HTTP/1.1,[http/1.1]}{127.0.0.1:60276}
[junit4] 2> 1422751 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.Server Started @1428324ms
[junit4] 2> 1422751 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\tempDir-001/jetty2, solrconfig=solrconfig.xml, hostContext=/, hostPort=60276, coreRootDirectory=C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-2-001\cores}
[junit4] 2> 1422755 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1422756 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1422756 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-2-001\solr.xml
[junit4] 2> 1422770 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1422771 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:60239/solr
[junit4] 2> 1422783 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1422787 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60276_ ] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
[junit4] 2> 1422794 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60276_ ] o.a.s.c.c.ZkStateReader Updating cluster state from ZooKeeper...
[junit4] 2> 1422795 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60276_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 1422800 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60276_ ] o.a.s.c.ZkController Publish node=127.0.0.1:60276_ as DOWN
[junit4] 2> 1422801 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60276_ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60276_
[junit4] 2> 1422802 INFO (OverseerStateUpdate-96649185664696324-127.0.0.1:60246_-n_0000000000) [n:127.0.0.1:60246_ ] o.a.s.c.o.NodeMutator DownNode state invoked for node: 127.0.0.1:60276_
[junit4] 2> 1422802 INFO (zkCallback-1722-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1422802 INFO (zkCallback-1734-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1422802 INFO (zkCallback-1718-thread-1-processing-n:127.0.0.1:60246_) [n:127.0.0.1:60246_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1422802 INFO (zkCallback-1728-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1422817 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60276_ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-2-001\cores
[junit4] 2> 1422817 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [n:127.0.0.1:60276_ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1422820 INFO (OverseerStateUpdate-96649185664696324-127.0.0.1:60246_-n_0000000000) [n:127.0.0.1:60246_ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 1422923 INFO (zkCallback-1728-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json] for collection [collection1] has occurred - updating... (live nodes size: [3])
[junit4] 2> 1422923 INFO (zkCallback-1734-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json] for collection [collection1] has occurred - updating... (live nodes size: [3])
[junit4] 2> 1423824 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 x:collection1] o.a.s.c.Config loaded config solrconfig.xml with version 0
[junit4] 2> 1423833 WARN (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 x:collection1] o.a.s.c.Config Beginning with Solr 5.5, <mergePolicy> is deprecated, use <mergePolicyFactory> instead.
[junit4] 2> 1423834 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1423851 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 x:collection1] o.a.s.c.SolrConfig Loaded SolrConfig: solrconfig.xml
[junit4] 2> 1423856 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1423937 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] default search field in schema is text. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 1423938 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] unique key field: id
[junit4] 2> 1423965 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1
[junit4] 2> 1423966 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-2-001\cores\collection1], dataDir=[C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-2-001\cores\collection1\data\]
[junit4] 2> 1423966 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2311d6ad
[junit4] 2> 1423967 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrCore New index directory detected: old=null new=C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-2-001\cores\collection1\data\index/
[junit4] 2> 1423967 WARN (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrCore [collection1] Solr index directory 'C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-2-001\cores\collection1\data\index' doesn't exist. Creating new index...
[junit4] 2> 1423968 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=28, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=83.6923828125, floorSegmentMB=0.685546875, forceMergeDeletesPctAllowed=26.134585952057705, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1423968 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrDeletionPolicy SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@426b4a30 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@49171931),segFN=segments_1,generation=1}
[junit4] 2> 1423968 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrDeletionPolicy newest commit generation = 1
[junit4] 2> 1423969 WARN (OldIndexDirectoryCleanupThreadForCore-collection1) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.DirectoryFactory C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-2-001\cores\collection1\data\ does not point to a valid data directory; skipping clean-up of old index directories.
[junit4] 2> 1423971 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 1423971 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "dedupe"
[junit4] 2> 1423971 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 1423971 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 1423971 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 1423971 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 1423972 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1423972 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 1423972 WARN (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,args = {defaults={a=A,b=B}}}
[junit4] 2> 1423986 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.PluginBag [collection1] Initialized 25 plugins of type requestHandler: [/update, /update/json, /update/csv, /update/json/docs, /config, /schema, /replication, /get, /admin/ping, /admin/segments, /admin/luke, /admin/system, /admin/mbeans, /admin/plugins, /admin/threads, /admin/properties, /admin/logging, /admin/file, /export, /graph, /stream, /sql, /terms, standard, /dump]
[junit4] 2> 1423986 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.RequestHandlers Registered paths: /admin/mbeans,standard,/update/json/docs,/admin/luke,/export,/get,/admin/properties,/update/json,/admin/threads,/dump,/update/csv,/sql,/graph,/admin/segments,/admin/system,/replication,/config,/stream,/schema,/admin/plugins,/admin/logging,/admin/ping,/update,/admin/file,/terms
[junit4] 2> 1423988 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1423988 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1423989 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1423989 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1423998 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=32, maxMergeAtOnceExplicit=15, maxMergedSegmentMB=12.5205078125, floorSegmentMB=0.33203125, forceMergeDeletesPctAllowed=16.747310080744324, segmentsPerTier=46.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.285183366414781
[junit4] 2> 1423998 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrDeletionPolicy SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@426b4a30 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@49171931),segFN=segments_1,generation=1}
[junit4] 2> 1423998 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrDeletionPolicy newest commit generation = 1
[junit4] 2> 1423998 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@2136e78d[collection1] main]
[junit4] 2> 1423999 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.r.ManagedResourceStorage Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
[junit4] 2> 1424000 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1424000 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.r.RestManager Initializing RestManager with initArgs: {}
[junit4] 2> 1424000 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.r.ManagedResourceStorage Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1424000 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.r.ManagedResourceStorage No data found for znode /configs/conf1/_rest_managed.json
[junit4] 2> 1424000 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1424001 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.r.RestManager Initializing 0 registered ManagedResources
[junit4] 2> 1424001 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1424002 INFO (searcherExecutor-5423-thread-1-processing-n:127.0.0.1:60276_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@2136e78d[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1424002 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.UpdateLog Looking up max value of version field to seed version buckets
[junit4] 2> 1424002 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.VersionInfo Refreshing highest value of _version_ for 65536 version buckets from index
[junit4] 2> 1424002 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.VersionInfo No terms found for _version_, cannot seed version bucket highest value from index
[junit4] 2> 1424002 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1546386976853196800
[junit4] 2> 1424004 INFO (coreLoadExecutor-5422-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.UpdateLog Took 2.0ms to seed version buckets with highest version 1546386976853196800
[junit4] 2> 1424010 INFO (coreZkRegister-5417-thread-1-processing-n:127.0.0.1:60276_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ZkController Core needs to recover:collection1
[junit4] 2> 1424010 INFO (updateExecutor-1731-thread-1-processing-n:127.0.0.1:60276_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 1424010 INFO (recoveryExecutor-1732-thread-1-processing-n:127.0.0.1:60276_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true
[junit4] 2> 1424012 INFO (recoveryExecutor-1732-thread-1-processing-n:127.0.0.1:60276_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]]
[junit4] 2> 1424012 INFO (recoveryExecutor-1732-thread-1-processing-n:127.0.0.1:60276_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[collection1]
[junit4] 2> 1424012 INFO (recoveryExecutor-1732-thread-1-processing-n:127.0.0.1:60276_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 1424012 INFO (recoveryExecutor-1732-thread-1-processing-n:127.0.0.1:60276_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.RecoveryStrategy Publishing state of core [collection1] as recovering, leader is [http://127.0.0.1:60264/collection1/] and I am [http://127.0.0.1:60276/collection1/]
[junit4] 2> 1424014 INFO (recoveryExecutor-1732-thread-1-processing-n:127.0.0.1:60276_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:60264]; [WaitForState: action=PREPRECOVERY&core=collection1&nodeName=127.0.0.1:60276_&coreNodeName=core_node2&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
[junit4] 2> 1424019 INFO (qtp1765065468-10377) [n:127.0.0.1:60264_ ] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node2, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true
[junit4] 2> 1424020 INFO (qtp1765065468-10377) [n:127.0.0.1:60264_ ] o.a.s.h.a.PrepRecoveryOp Will wait a max of 183 seconds to see collection1 (shard1 of collection1) have state: recovering
[junit4] 2> 1424020 INFO (qtp1765065468-10377) [n:127.0.0.1:60264_ ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard1, thisCore=collection1, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:60276_, coreNodeName=core_node2, onlyIfActiveCheckResult=false, nodeProps: core_node2:{"core":"collection1","base_url":"http://127.0.0.1:60276","node_name":"127.0.0.1:60276_","state":"down"}
[junit4] 2> 1424120 INFO (zkCallback-1734-thread-1-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json] for collection [collection1] has occurred - updating... (live nodes size: [3])
[junit4] 2> 1424120 INFO (zkCallback-1728-thread-1-processing-n:127.0.0.1:60264_) [n:127.0.0.1:60264_ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json] for collection [collection1] has occurred - updating... (live nodes size: [3])
[junit4] 2> 1424323 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.SolrTestCaseJ4 ###Starting test
[junit4] 2> 1424334 INFO (qtp1117641394-10340) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[2-0 (1546386977197129728)]} 0 3
[junit4] 2> 1424334 INFO (qtp1117641394-10341) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[1-0 (1546386977197129729)]} 0 3
[junit4] 2> 1424348 INFO (qtp1411436059-10407) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:60264/collection1/&wt=javabin&version=2}{add=[1-0 (1546386977205518337)]} 0 1
[junit4] 2> 1424348 INFO (qtp1411436059-10408) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:60264/collection1/&wt=javabin&version=2}{add=[2-0 (1546386977205518336)]} 0 1
[junit4] 2> 1424348 INFO (qtp1765065468-10380) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[1-0 (1546386977205518337)]} 0 10
[junit4] 2> 1424348 INFO (qtp1765065468-10378) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[2-0 (1546386977205518336)]} 0 11
[junit4] 2> 1424351 INFO (qtp1117641394-10342) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[2-1 (1546386977218101248)]} 0 0
[junit4] 2> 1424351 INFO (qtp1117641394-10343) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[1-1 (1546386977218101249)]} 0 0
[junit4] 2> 1424353 INFO (qtp1411436059-10409) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:60264/collection1/&wt=javabin&version=2}{add=[2-1 (1546386977220198400)]} 0 0
[junit4] 2> 1424353 INFO (qtp1765065468-10382) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[2-1 (1546386977220198400)]} 0 1
[junit4] 2> 1424355 INFO (qtp1411436059-10410) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:60264/collection1/&wt=javabin&version=2}{add=[1-1 (1546386977221246976)]} 0 0
[junit4] 2> 1424355 INFO (qtp1117641394-10344) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{delete=[2-1 (-1546386977223344128)]} 0 0
[junit4] 2> 1424355 INFO (qtp1765065468-10381) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[1-1 (1546386977221246976)]} 0 2
[junit4] 2> 1424356 INFO (qtp1117641394-10339) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{delete=[1-1 (-1546386977224392704)]} 0 0
[junit4] 2> 1424359 INFO (qtp1411436059-10411) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:60264/collection1/&wt=javabin&version=2}{delete=[2-1 (-1546386977225441280)]} 0 0
[junit4] 2> 1424361 INFO (qtp1765065468-10375) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{delete=[2-1 (-1546386977225441280)]} 0 3
[junit4] 2> 1424362 INFO (qtp1411436059-10404) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:60264/collection1/&wt=javabin&version=2}{delete=[1-1 (-1546386977227538432)]} 0 0
[junit4] 2> 1424364 INFO (qtp1765065468-10379) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{delete=[1-1 (-1546386977227538432)]} 0 3
[junit4] 2> 1424364 INFO (qtp1117641394-10337) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[2-2 (1546386977230684160)]} 0 0
[junit4] 2> 1424367 INFO (qtp1117641394-10341) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[1-2 (1546386977235927040)]} 0 0
[junit4] 2> 1424369 INFO (qtp1411436059-10406) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:60264/collection1/&wt=javabin&version=2}{add=[2-2 (1546386977234878464)]} 0 0
[junit4] 2> 1424371 INFO (qtp1765065468-10380) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[2-2 (1546386977234878464)]} 0 4
[junit4] 2> 1424374 INFO (qtp1117641394-10340) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[2-3 (1546386977241169920)]} 0 1
[junit4] 2> 1424375 INFO (qtp1411436059-10407) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:60264/collection1/&wt=javabin&version=2}{add=[1-2 (1546386977240121344)]} 0 0
[junit4] 2> 1424375 INFO (qtp1765065468-10378) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[1-2 (1546386977240121344)]} 0 4
[junit4] 2> 1424377 INFO (qtp1117641394-10342) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[1-3 (1546386977246412800)]} 0 0
[junit4] 2> 1424379 INFO (qtp1411436059-10408) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:60264/collection1/&wt=javabin&version=2}{add=[2-3 (1546386977246412800)]} 0 0
[junit4] 2> 1424379 INFO (qtp1765065468-10380) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[2-3 (1546386977246412800)]} 0 2
[junit4] 2> 1424380 INFO (qtp1411436059-10409) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:60264/collection1/&wt=javabin&version=2}{add=[1-3 (1546386977248509952)]} 0 0
[junit4] 2> 1424380 INFO (qtp1117641394-10343) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[2-4 (1546386977249558528)]} 0 0
[junit4] 2> 1424380 INFO (qtp1765065468-10381) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[1-3 (1546386977248509952)]} 0 1
[junit4] 2> 1424382 INFO (qtp1117641394-10344) [n:127.0.0.1:60246_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[1-4 (1546386977251655680)]} 0 0
[junit4] 2> 1424384 INFO (qtp1411436059-10410) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:60264/collection1/&wt=javabin&version=2}{add=[2-4 (1546386977251655680)]} 0 0
[junit4] 2> 1424386 INFO (qtp1765065468-10375) [n:127.0.0.1:60264_ c:collection1 s:shard1 r:core_node1 x:collection1] o.a.s.u.p.Lo
[...truncated too long message...]
core_node2 x:collection1] o.a.s.c.CachingDirectoryFactory Closing directory, CoreContainer#isShutdown=true
[junit4] 2> 1456009 INFO (zkCallback-1741-thread-2-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.CachingDirectoryFactory Closing directory: C:\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\..\..\..\..\..\..\..\..\..\Users\jenkins\workspace\Lucene-Solr-6.x-Windows\solr\build\solr-core\test\J1\temp\solr.cloud.RecoveryZkTest_68A817BFFB88BCDF-001\shard-2-001\cores\collection1\data\
[junit4] 2> 1456009 INFO (zkCallback-1741-thread-2-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ElectionContext Canceling election /collections/collection1/leader_elect/shard1/election/96649185664696335-core_node2-n_0000000002
[junit4] 2> 1456511 WARN (zkCallback-1741-thread-3-processing-n:127.0.0.1:60276_) [n:127.0.0.1:60276_ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 1456513 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.ServerConnector Stopped ServerConnector@68f3c14c{HTTP/1.1,[http/1.1]}{127.0.0.1:60276}
[junit4] 2> 1456513 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@e391b8a{/,null,UNAVAILABLE}
[junit4] 2> 1456515 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x1575dec1b600005, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 1456516 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.ChaosMonkey monkey: stop shard! 60246
[junit4] 2> 1456516 INFO (TEST-RecoveryZkTest.test-seed#[68A817BFFB88BCDF]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:60239 60239
[junit4] 2> 1456518 INFO (Thread-2366) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:60239 60239
[junit4] 2> 1456519 WARN (Thread-2366) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 5 /solr/aliases.json
[junit4] 2> 5 /solr/clusterprops.json
[junit4] 2> 4 /solr/security.json
[junit4] 2> 4 /solr/configs/conf1
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 5 /solr/clusterstate.json
[junit4] 2> 3 /solr/collections/collection1/state.json
[junit4] 2> 2 /solr/collections/collection1/leader_elect/shard1/election/96649185664696329-core_node1-n_0000000000
[junit4] 2> 2 /solr/overseer_elect/election/96649185664696329-127.0.0.1:60264_-n_0000000001
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 117 /solr/overseer/queue
[junit4] 2> 36 /solr/overseer/collection-queue-work
[junit4] 2> 14 /solr/overseer/queue-work
[junit4] 2> 5 /solr/collections
[junit4] 2> 4 /solr/live_nodes
[junit4] 2>
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest -Dtests.method=test -Dtests.seed=68A817BFFB88BCDF -Dtests.slow=true -Dtests.locale=sl-SI -Dtests.timezone=Antarctica/Vostok -Dtests.asserts=true -Dtests.file.encoding=US-ASCII
[junit4] ERROR 38.5s J1 | RecoveryZkTest.test <<<
[junit4] > Throwable #1: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=10444, name=updateExecutor-1725-thread-2, state=RUNNABLE, group=TGRP-RecoveryZkTest]
[junit4] > at __randomizedtesting.SeedInfo.seed([68A817BFFB88BCDF:E0FC28655574D127]:0)
[junit4] > Caused by: org.apache.solr.common.SolrException: Replica: http://127.0.0.1:60276/collection1/ should have been marked under leader initiated recovery in ZkController but wasn't.
[junit4] > at __randomizedtesting.SeedInfo.seed([68A817BFFB88BCDF]:0)
[junit4] > at org.apache.solr.cloud.LeaderInitiatedRecoveryThread.run(LeaderInitiatedRecoveryThread.java:88)
[junit4] > at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 1456522 INFO (SUITE-RecoveryZkTest-seed#[68A817BFFB88BCDF]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> Sep 24, 2016 8:39:35 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene62): {rnd_b=PostingsFormat(name=LuceneFixedGap), _version_=FST50, a_t=FST50, a_i=PostingsFormat(name=LuceneFixedGap), id=PostingsFormat(name=LuceneFixedGap)}, docValues:{}, maxPointsInLeafNode=1129, maxMBSortInHeap=5.15123670544535, sim=RandomSimilarity(queryNorm=true,coord=no): {}, locale=sl-SI, timezone=Antarctica/Vostok
[junit4] 2> NOTE: Windows 10 10.0 amd64/Oracle Corporation 1.8.0_102 (64-bit)/cpus=3,threads=1,free=103784776,total=241717248
[junit4] 2> NOTE: All tests run in this JVM: [ResponseHeaderTest, TestReload, BinaryUpdateRequestHandlerTest, DistribDocExpirationUpdateProcessorTest, DeleteLastCustomShardedReplicaTest, WordBreakSolrSpellCheckerTest, TestFieldCollectionResource, TestSimpleTrackingShardHandler, PreAnalyzedFieldTest, TestComplexPhraseQParserPlugin, UUIDUpdateProcessorFallbackTest, SimpleMLTQParserTest, TestSchemaNameResource, SSLMigrationTest, TestStressCloudBlindAtomicUpdates, TestSubQueryTransformer, TestIntervalFaceting, TestDistributedGrouping, CoreMergeIndexesAdminHandlerTest, TestQueryTypes, TestDistributedMissingSort, TestMacros, AutoCommitTest, TestReversedWildcardFilterFactory, TestHdfsCloudBackupRestore, SpellCheckComponentTest, TestQuerySenderListener, TestUtils, TestCopyFieldCollectionResource, TestLMJelinekMercerSimilarityFactory, StatsReloadRaceTest, TestRandomRequestDistribution, TestLeaderInitiatedRecoveryThread, URLClassifyProcessorTest, AddBlockUpdateTest, TestTrieFacet, TestSolrDeletionPolicy2, TestPivotHelperCode, BasicFunctionalityTest, CloudExitableDirectoryReaderTest, CSVRequestHandlerTest, DefaultValueUpdateProcessorTest, SolrXmlInZkTest, TestRandomCollapseQParserPlugin, CurrencyFieldOpenExchangeTest, QueryParsingTest, ScriptEngineTest, TestDFISimilarityFactory, TestDistributedStatsComponentCardinality, FieldAnalysisRequestHandlerTest, DebugComponentTest, TestExactStatsCache, SolrIndexSplitterTest, FileBasedSpellCheckerTest, ReturnFieldsTest, TestScoreJoinQPNoScore, ParsingFieldUpdateProcessorsTest, CollectionStateFormat2Test, TestLuceneMatchVersion, TestDocSet, TestRawTransformer, TestSchemaSimilarityResource, SpellCheckCollatorTest, RAMDirectoryFactoryTest, TestDocTermOrds, HLLUtilTest, AddSchemaFieldsUpdateProcessorFactoryTest, SpatialRPTFieldTypeTest, TestBadConfig, CdcrRequestHandlerTest, TestRandomFaceting, TestManagedResourceStorage, TestIndexSearcher, JavabinLoaderTest, CoreAdminCreateDiscoverTest, TestFileDictionaryLookup, CoreAdminHandlerTest, ZkSolrClientTest, TestIndexingPerformance, TestFuzzyAnalyzedSuggestions, BlockJoinFacetDistribTest, CopyFieldTest, DateMathParserTest, TestManagedStopFilterFactory, BlobRepositoryCloudTest, TestLockTree, TestPHPSerializedResponseWriter, DeleteReplicaTest, TestReloadAndDeleteDocs, TestDownShardTolerantSearch, TestConfigSets, TestJmxMonitoredMap, TestConfigReload, HdfsNNFailoverTest, FieldMutatingUpdateProcessorTest, TestImplicitCoreProperties, TestOnReconnectListenerSupport, TestLegacyFieldCache, BadCopyFieldTest, BitVectorTest, HdfsDirectoryFactoryTest, ChaosMonkeySafeLeaderTest, TestFieldCacheReopen, ShowFileRequestHandlerTest, SignatureUpdateProcessorFactoryTest, SuggestComponentContextFilterQueryTest, TestRuleBasedAuthorizationPlugin, SuggesterWFSTTest, TestBackupRepositoryFactory, LeaderInitiatedRecoveryOnCommitTest, TestNumericTerms64, ClusterStateTest, SortSpecParsingTest, TestGraphTermsQParserPlugin, TestFiltering, TestSchemaManager, BigEndianAscendingWordDeserializerTest, TestLMDirichletSimilarityFactory, TestRestoreCore, TestConfigSetsAPIExclusivity, TestTolerantUpdateProcessorCloud, SolrIndexConfigTest, TestMissingGroups, ConnectionReuseTest, SearchHandlerTest, TestSolr4Spatial2, FullSolrCloudDistribCmdsTest, DocExpirationUpdateProcessorFactoryTest, CachingDirectoryFactoryTest, TestInitQParser, TestHighFrequencyDictionaryFactory, TestJoin, TestReloadDeadlock, IndexSchemaTest, TestDynamicFieldCollectionResource, TestSimpleQParserPlugin, TestRangeQuery, BlockJoinFacetSimpleTest, TestCoreDiscovery, CollectionsAPIAsyncDistributedZkTest, TestManagedSchema, CheckHdfsIndexTest, DirectUpdateHandlerOptimizeTest, BaseCdcrDistributedZkTest, TestSolrCLIRunExample, HdfsBasicDistributedZkTest, TestDocBasedVersionConstraints, ConvertedLegacyTest, OverseerRolesTest, TestXmlQParserPlugin, RegexBoostProcessorTest, TestCloudManagedSchema, TestSerializedLuceneMatchVersion, BasicDistributedZk2Test, CollectionsAPIDistributedZkTest, OpenCloseCoreStressTest, LeaderElectionIntegrationTest, ShardRoutingTest, BasicZkTest, RecoveryZkTest]
[junit4] Completed [280/635 (1!)] on J1 in 39.11s, 1 test, 1 error <<< FAILURES!
[...truncated 61488 lines...]