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/10/19 17:46:26 UTC
[JENKINS] Lucene-Solr-6.x-Linux (64bit/jdk1.8.0_102) - Build # 1988
- Still Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Linux/1988/
Java: 64bit/jdk1.8.0_102 -XX:+UseCompressedOops -XX:+UseParallelGC
1 tests failed.
FAILED: org.apache.solr.update.processor.TestNamedUpdateProcessors.test
Error Message:
Error from server at https://127.0.0.1:44228/_ri/z/collection1: error instantiating class :org.apache.solr.update.processor.RuntimeUrp
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at https://127.0.0.1:44228/_ri/z/collection1: error instantiating class :org.apache.solr.update.processor.RuntimeUrp
at __randomizedtesting.SeedInfo.seed([6CA3AF470248E8E9:E4F7909DACB48511]:0)
at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:593)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:262)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:251)
at org.apache.solr.client.solrj.SolrClient.request(SolrClient.java:1219)
at org.apache.solr.update.processor.TestNamedUpdateProcessors.test(TestNamedUpdateProcessors.java:125)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1764)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:871)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:921)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:992)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:967)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:809)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:460)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:880)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:781)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:816)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:827)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 12707 lines...]
[junit4] Suite: org.apache.solr.update.processor.TestNamedUpdateProcessors
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/init-core-data-001
[junit4] 2> 1843187 INFO (SUITE-TestNamedUpdateProcessors-seed#[6CA3AF470248E8E9]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
[junit4] 2> 1843188 INFO (SUITE-TestNamedUpdateProcessors-seed#[6CA3AF470248E8E9]-worker) [ ] o.a.s.BaseDistributedSearchTestCase Setting hostContext system property: /_ri/z
[junit4] 2> 1843190 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 1843193 INFO (Thread-4190) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1843194 INFO (Thread-4190) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 1843294 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.ZkTestServer start zk server on port:39307
[junit4] 2> 1843299 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 1843300 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4] 2> 1843300 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 1843301 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 1843302 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 1843303 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4] 2> 1843303 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml
[junit4] 2> 1843304 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 1843304 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 1843305 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 1843305 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 1843359 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/control-001/cores/collection1
[junit4] 2> 1843361 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1843362 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@4d38c047{/_ri/z,null,AVAILABLE}
[junit4] 2> 1843363 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.ServerConnector Started ServerConnector@1040d228{SSL,[ssl, http/1.1]}{127.0.0.1:36523}
[junit4] 2> 1843363 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.Server Started @1844915ms
[junit4] 2> 1843363 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/tempDir-001/control/data, hostContext=/_ri/z, hostPort=36523, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/control-001/cores}
[junit4] 2> 1843363 ERROR (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1843363 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.3.0
[junit4] 2> 1843363 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1843364 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1843364 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-10-19T17:27:17.424Z
[junit4] 2> 1843365 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1843365 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/control-001/solr.xml
[junit4] 2> 1843369 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1843369 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39307/solr
[junit4] 2> 1843377 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:36523__ri%2Fz
[junit4] 2> 1843378 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.Overseer Overseer (id=96789989769478149-127.0.0.1:36523__ri%2Fz-n_0000000000) starting
[junit4] 2> 1843380 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36523__ri%2Fz
[junit4] 2> 1843381 INFO (zkCallback-3146-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1843388 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/control-001/cores
[junit4] 2> 1843388 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1843389 INFO (OverseerStateUpdate-96789989769478149-127.0.0.1:36523__ri%2Fz-n_0000000000) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 1844396 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz c:control_collection x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1844409 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz c:control_collection x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1844457 WARN (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz 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> 1844459 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz c:control_collection x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 1844463 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz c:control_collection x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection control_collection
[junit4] 2> 1844464 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/control-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/control-001/cores/collection1/data/]
[junit4] 2> 1844464 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz 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@5b62428
[junit4] 2> 1844464 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz 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=47, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=8.6787109375, floorSegmentMB=0.560546875, forceMergeDeletesPctAllowed=29.873990069798225, segmentsPerTier=12.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1844467 WARN (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz 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> 1844476 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz 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> 1844476 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz 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> 1844477 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1844477 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1844477 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz 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=37, maxMergeAtOnceExplicit=43, maxMergedSegmentMB=53.3212890625, floorSegmentMB=0.85546875, forceMergeDeletesPctAllowed=27.67398114578031, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.23354800786165894
[junit4] 2> 1844478 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1bd2c6c[collection1] main]
[junit4] 2> 1844478 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1844478 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz 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> 1844478 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1844479 INFO (searcherExecutor-8575-thread-1-processing-n:127.0.0.1:36523__ri%2Fz x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@1bd2c6c[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1844479 INFO (coreLoadExecutor-8574-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz 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 1548639837659070464
[junit4] 2> 1844483 INFO (coreZkRegister-8567-thread-1-processing-n:127.0.0.1:36523__ri%2Fz x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1844483 INFO (coreZkRegister-8567-thread-1-processing-n:127.0.0.1:36523__ri%2Fz x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:36523__ri%2Fz 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> 1844483 INFO (coreZkRegister-8567-thread-1-processing-n:127.0.0.1:36523__ri%2Fz x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:36523/_ri/z/collection1/
[junit4] 2> 1844483 INFO (coreZkRegister-8567-thread-1-processing-n:127.0.0.1:36523__ri%2Fz x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1844483 INFO (coreZkRegister-8567-thread-1-processing-n:127.0.0.1:36523__ri%2Fz x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy https://127.0.0.1:36523/_ri/z/collection1/ has no replicas
[junit4] 2> 1844484 INFO (coreZkRegister-8567-thread-1-processing-n:127.0.0.1:36523__ri%2Fz x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:36523/_ri/z/collection1/ shard1
[junit4] 2> 1844635 INFO (coreZkRegister-8567-thread-1-processing-n:127.0.0.1:36523__ri%2Fz x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:36523__ri%2Fz c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1844891 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1844891 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.ChaosMonkey monkey: init - expire sessions:false cause connection loss:false
[junit4] 2> 1844891 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractFullDistribZkTestBase Creating collection1 with stateFormat=2
[junit4] 2> 1844947 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-1-001/cores/collection1
[junit4] 2> 1844947 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 1 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-1-001
[junit4] 2> 1844948 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1844949 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@31e185c9{/_ri/z,null,AVAILABLE}
[junit4] 2> 1844951 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.ServerConnector Started ServerConnector@6b3164e4{SSL,[ssl, http/1.1]}{127.0.0.1:43277}
[junit4] 2> 1844951 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.Server Started @1846503ms
[junit4] 2> 1844951 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/tempDir-001/jetty1, solrconfig=solrconfig.xml, hostContext=/_ri/z, hostPort=43277, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-1-001/cores}
[junit4] 2> 1844951 ERROR (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1844951 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.3.0
[junit4] 2> 1844952 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1844952 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1844952 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-10-19T17:27:19.012Z
[junit4] 2> 1844953 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1844953 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-1-001/solr.xml
[junit4] 2> 1844959 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1844960 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39307/solr
[junit4] 2> 1844964 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1844965 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43277__ri%2Fz
[junit4] 2> 1844965 INFO (zkCallback-3146-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1844966 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1844966 INFO (zkCallback-3150-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1844974 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-1-001/cores
[junit4] 2> 1844975 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1844975 INFO (OverseerStateUpdate-96789989769478149-127.0.0.1:36523__ri%2Fz-n_0000000000) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 1845077 WARN (OverseerStateUpdate-96789989769478149-127.0.0.1:36523__ri%2Fz-n_0000000000) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.Overseer Bad version writing to ZK using compare-and-set, will force refresh cluster state: KeeperErrorCode = BadVersion for /collections/collection1/state.json
[junit4] 2> 1845078 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] 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> 1845078 INFO (OverseerStateUpdate-96789989769478149-127.0.0.1:36523__ri%2Fz-n_0000000000) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 1845079 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] 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> 1845981 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1845990 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1846041 WARN (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz 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> 1846042 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 1846047 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1
[junit4] 2> 1846047 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-1-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-1-001/cores/collection1/data/]
[junit4] 2> 1846047 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 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@5b62428
[junit4] 2> 1846048 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=47, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=8.6787109375, floorSegmentMB=0.560546875, forceMergeDeletesPctAllowed=29.873990069798225, segmentsPerTier=12.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1846051 WARN (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 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> 1846056 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1846056 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1846057 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1846057 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1846058 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=37, maxMergeAtOnceExplicit=43, maxMergedSegmentMB=53.3212890625, floorSegmentMB=0.85546875, forceMergeDeletesPctAllowed=27.67398114578031, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.23354800786165894
[junit4] 2> 1846058 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@2d9110d6[collection1] main]
[junit4] 2> 1846059 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1846059 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1846059 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1846059 INFO (searcherExecutor-8586-thread-1-processing-n:127.0.0.1:43277__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@2d9110d6[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1846060 INFO (coreLoadExecutor-8585-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1548639839316869120
[junit4] 2> 1846063 INFO (coreZkRegister-8580-thread-1-processing-n:127.0.0.1:43277__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1846063 INFO (coreZkRegister-8580-thread-1-processing-n:127.0.0.1:43277__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1846063 INFO (coreZkRegister-8580-thread-1-processing-n:127.0.0.1:43277__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:43277/_ri/z/collection1/
[junit4] 2> 1846063 INFO (coreZkRegister-8580-thread-1-processing-n:127.0.0.1:43277__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1846064 INFO (coreZkRegister-8580-thread-1-processing-n:127.0.0.1:43277__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SyncStrategy https://127.0.0.1:43277/_ri/z/collection1/ has no replicas
[junit4] 2> 1846065 INFO (coreZkRegister-8580-thread-1-processing-n:127.0.0.1:43277__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:43277/_ri/z/collection1/ shard2
[junit4] 2> 1846166 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] 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> 1846215 INFO (coreZkRegister-8580-thread-1-processing-n:127.0.0.1:43277__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:43277__ri%2Fz c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1846317 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] 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> 1846531 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-2-001/cores/collection1
[junit4] 2> 1846531 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 2 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-2-001
[junit4] 2> 1846532 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1846532 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@e93aeaa{/_ri/z,null,AVAILABLE}
[junit4] 2> 1846533 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.ServerConnector Started ServerConnector@23b7c40b{SSL,[ssl, http/1.1]}{127.0.0.1:39844}
[junit4] 2> 1846534 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.Server Started @1848086ms
[junit4] 2> 1846534 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/tempDir-001/jetty2, solrconfig=solrconfig.xml, hostContext=/_ri/z, hostPort=39844, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-2-001/cores}
[junit4] 2> 1846534 ERROR (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1846534 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.3.0
[junit4] 2> 1846534 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1846534 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1846534 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-10-19T17:27:20.594Z
[junit4] 2> 1846536 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1846536 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-2-001/solr.xml
[junit4] 2> 1846540 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1846540 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39307/solr
[junit4] 2> 1846544 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:39844__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 1846545 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:39844__ri%2Fz ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39844__ri%2Fz
[junit4] 2> 1846546 INFO (zkCallback-3146-thread-1-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1846546 INFO (zkCallback-3150-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1846546 INFO (zkCallback-3162-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1846546 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1846554 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:39844__ri%2Fz ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-2-001/cores
[junit4] 2> 1846554 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:39844__ri%2Fz ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1846555 INFO (OverseerStateUpdate-96789989769478149-127.0.0.1:36523__ri%2Fz-n_0000000000) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 1846656 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] 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> 1846656 INFO (zkCallback-3162-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz ] 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> 1847560 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1847569 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1847621 WARN (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz 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> 1847622 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 1847627 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1
[junit4] 2> 1847627 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-2-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-2-001/cores/collection1/data/]
[junit4] 2> 1847628 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz 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@5b62428
[junit4] 2> 1847628 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=47, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=8.6787109375, floorSegmentMB=0.560546875, forceMergeDeletesPctAllowed=29.873990069798225, segmentsPerTier=12.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1847631 WARN (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz 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> 1847636 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1847636 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz 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> 1847636 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1847637 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1847637 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=37, maxMergeAtOnceExplicit=43, maxMergedSegmentMB=53.3212890625, floorSegmentMB=0.85546875, forceMergeDeletesPctAllowed=27.67398114578031, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.23354800786165894
[junit4] 2> 1847638 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@7f8f6c7a[collection1] main]
[junit4] 2> 1847638 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1847638 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz 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> 1847638 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1847639 INFO (searcherExecutor-8597-thread-1-processing-n:127.0.0.1:39844__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@7f8f6c7a[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1847639 INFO (coreLoadExecutor-8596-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz 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 1548639840972570624
[junit4] 2> 1847642 INFO (coreZkRegister-8591-thread-1-processing-n:127.0.0.1:39844__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1847643 INFO (coreZkRegister-8591-thread-1-processing-n:127.0.0.1:39844__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1847643 INFO (coreZkRegister-8591-thread-1-processing-n:127.0.0.1:39844__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:39844/_ri/z/collection1/
[junit4] 2> 1847643 INFO (coreZkRegister-8591-thread-1-processing-n:127.0.0.1:39844__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1847643 INFO (coreZkRegister-8591-thread-1-processing-n:127.0.0.1:39844__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SyncStrategy https://127.0.0.1:39844/_ri/z/collection1/ has no replicas
[junit4] 2> 1847644 INFO (coreZkRegister-8591-thread-1-processing-n:127.0.0.1:39844__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:39844/_ri/z/collection1/ shard1
[junit4] 2> 1847745 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] 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> 1847745 INFO (zkCallback-3162-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz ] 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> 1847794 INFO (coreZkRegister-8591-thread-1-processing-n:127.0.0.1:39844__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:39844__ri%2Fz c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1847896 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] 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> 1847896 INFO (zkCallback-3162-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz ] 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> 1848107 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-3-001/cores/collection1
[junit4] 2> 1848108 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 3 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-3-001
[junit4] 2> 1848109 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1848109 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@6c930677{/_ri/z,null,AVAILABLE}
[junit4] 2> 1848110 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.ServerConnector Started ServerConnector@22927bdd{SSL,[ssl, http/1.1]}{127.0.0.1:41205}
[junit4] 2> 1848110 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.Server Started @1849663ms
[junit4] 2> 1848110 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/tempDir-001/jetty3, solrconfig=solrconfig.xml, hostContext=/_ri/z, hostPort=41205, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-3-001/cores}
[junit4] 2> 1848111 ERROR (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1848111 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.3.0
[junit4] 2> 1848111 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1848111 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1848111 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-10-19T17:27:22.171Z
[junit4] 2> 1848112 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1848113 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-3-001/solr.xml
[junit4] 2> 1848117 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1848117 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39307/solr
[junit4] 2> 1848120 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:41205__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3)
[junit4] 2> 1848122 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:41205__ri%2Fz ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41205__ri%2Fz
[junit4] 2> 1848122 INFO (zkCallback-3162-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 1848122 INFO (zkCallback-3146-thread-3-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 1848123 INFO (zkCallback-3168-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 1848122 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 1848122 INFO (zkCallback-3150-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 1848132 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:41205__ri%2Fz ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-3-001/cores
[junit4] 2> 1848132 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:41205__ri%2Fz ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1848133 INFO (OverseerStateUpdate-96789989769478149-127.0.0.1:36523__ri%2Fz-n_0000000000) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 1848234 INFO (zkCallback-3162-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz ] 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: [4])
[junit4] 2> 1848234 INFO (zkCallback-3168-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz ] 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: [4])
[junit4] 2> 1848234 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] 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: [4])
[junit4] 2> 1849139 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1849148 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1849199 WARN (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz 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> 1849200 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 1849205 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1
[junit4] 2> 1849206 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-3-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-3-001/cores/collection1/data/]
[junit4] 2> 1849206 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5b62428
[junit4] 2> 1849207 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=47, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=8.6787109375, floorSegmentMB=0.560546875, forceMergeDeletesPctAllowed=29.873990069798225, segmentsPerTier=12.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1849210 WARN (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 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> 1849215 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1849215 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1849216 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1849216 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1849217 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=37, maxMergeAtOnceExplicit=43, maxMergedSegmentMB=53.3212890625, floorSegmentMB=0.85546875, forceMergeDeletesPctAllowed=27.67398114578031, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.23354800786165894
[junit4] 2> 1849218 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@2af42d8f[collection1] main]
[junit4] 2> 1849218 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1849218 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1849218 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1849219 INFO (searcherExecutor-8608-thread-1-processing-n:127.0.0.1:41205__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@2af42d8f[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1849219 INFO (coreLoadExecutor-8607-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1548639842629320704
[junit4] 2> 1849222 INFO (coreZkRegister-8602-thread-1-processing-n:127.0.0.1:41205__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.ZkController Core needs to recover:collection1
[junit4] 2> 1849222 INFO (updateExecutor-3165-thread-1-processing-n:127.0.0.1:41205__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 1849222 INFO (recoveryExecutor-3166-thread-1-processing-n:127.0.0.1:41205__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true
[junit4] 2> 1849223 INFO (recoveryExecutor-3166-thread-1-processing-n:127.0.0.1:41205__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]]
[junit4] 2> 1849223 INFO (recoveryExecutor-3166-thread-1-processing-n:127.0.0.1:41205__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[collection1]
[junit4] 2> 1849223 INFO (recoveryExecutor-3166-thread-1-processing-n:127.0.0.1:41205__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 1849223 INFO (recoveryExecutor-3166-thread-1-processing-n:127.0.0.1:41205__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Publishing state of core [collection1] as recovering, leader is [https://127.0.0.1:43277/_ri/z/collection1/] and I am [https://127.0.0.1:41205/_ri/z/collection1/]
[junit4] 2> 1849224 INFO (recoveryExecutor-3166-thread-1-processing-n:127.0.0.1:41205__ri%2Fz x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:41205__ri%2Fz c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Sending prep recovery command to [https://127.0.0.1:43277/_ri/z]; [WaitForState: action=PREPRECOVERY&core=collection1&nodeName=127.0.0.1:41205__ri%252Fz&coreNodeName=core_node3&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
[junit4] 2> 1849276 INFO (qtp1277508752-16788) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true
[junit4] 2> 1849276 INFO (qtp1277508752-16788) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.h.a.PrepRecoveryOp Will wait a max of 183 seconds to see collection1 (shard2 of collection1) have state: recovering
[junit4] 2> 1849276 INFO (qtp1277508752-16788) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard2, thisCore=collection1, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:41205__ri%2Fz, coreNodeName=core_node3, onlyIfActiveCheckResult=false, nodeProps: core_node3:{"core":"collection1","base_url":"https://127.0.0.1:41205/_ri/z","node_name":"127.0.0.1:41205__ri%2Fz","state":"down"}
[junit4] 2> 1849325 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] 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: [4])
[junit4] 2> 1849325 INFO (zkCallback-3162-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz ] 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: [4])
[junit4] 2> 1849325 INFO (zkCallback-3168-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz ] 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: [4])
[junit4] 2> 1849684 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-4-001/cores/collection1
[junit4] 2> 1849684 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 4 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-4-001
[junit4] 2> 1849685 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1849686 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@12e78734{/_ri/z,null,AVAILABLE}
[junit4] 2> 1849687 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.ServerConnector Started ServerConnector@6a125d25{SSL,[ssl, http/1.1]}{127.0.0.1:44228}
[junit4] 2> 1849687 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.e.j.s.Server Started @1851239ms
[junit4] 2> 1849687 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/tempDir-001/jetty4, solrconfig=solrconfig.xml, hostContext=/_ri/z, hostPort=44228, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-4-001/cores}
[junit4] 2> 1849687 ERROR (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1849687 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.3.0
[junit4] 2> 1849687 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1849687 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1849687 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-10-19T17:27:23.747Z
[junit4] 2> 1849689 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1849689 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-4-001/solr.xml
[junit4] 2> 1849700 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1849700 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39307/solr
[junit4] 2> 1849705 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:44228__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 1849706 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:44228__ri%2Fz ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44228__ri%2Fz
[junit4] 2> 1849707 INFO (zkCallback-3146-thread-2-processing-n:127.0.0.1:36523__ri%2Fz) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 1849707 INFO (zkCallback-3162-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 1849708 INFO (zkCallback-3175-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 1849707 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 1849707 INFO (zkCallback-3150-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 1849707 INFO (zkCallback-3168-thread-1-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 1849723 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:44228__ri%2Fz ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-4-001/cores
[junit4] 2> 1849723 INFO (TEST-TestNamedUpdateProcessors.test-seed#[6CA3AF470248E8E9]) [n:127.0.0.1:44228__ri%2Fz ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1849724 INFO (OverseerStateUpdate-96789989769478149-127.0.0.1:36523__ri%2Fz-n_0000000000) [n:127.0.0.1:36523__ri%2Fz ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 1849826 INFO (zkCallback-3168-thread-2-processing-n:127.0.0.1:41205__ri%2Fz) [n:127.0.0.1:41205__ri%2Fz ] 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: [5])
[junit4] 2> 1849826 INFO (zkCallback-3162-thread-1-processing-n:127.0.0.1:39844__ri%2Fz) [n:127.0.0.1:39844__ri%2Fz ] 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: [5])
[junit4] 2> 1849826 INFO (zkCallback-3175-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz ] 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: [5])
[junit4] 2> 1849826 INFO (zkCallback-3156-thread-1-processing-n:127.0.0.1:43277__ri%2Fz) [n:127.0.0.1:43277__ri%2Fz ] 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: [5])
[junit4] 2> 1850276 INFO (qtp1277508752-16788) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard2, thisCore=collection1, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=recovering, localState=active, nodeName=127.0.0.1:41205__ri%2Fz, coreNodeName=core_node3, onlyIfActiveCheckResult=false, nodeProps: core_node3:{"core":"collection1","base_url":"https://127.0.0.1:41205/_ri/z","node_name":"127.0.0.1:41205__ri%2Fz","state":"recovering"}
[junit4] 2> 1850276 INFO (qtp1277508752-16788) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.h.a.PrepRecoveryOp Waited coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4] 2> 1850277 INFO (qtp1277508752-16788) [n:127.0.0.1:43277__ri%2Fz ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:41205__ri%252Fz&onlyIfLeaderActive=true&core=collection1&coreNodeName=core_node3&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=1000
[junit4] 2> 1850730 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1850739 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1850792 WARN (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz 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> 1850794 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 1850799 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1
[junit4] 2> 1850799 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-4-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001/shard-4-001/cores/collection1/data/]
[junit4] 2> 1850799 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5b62428
[junit4] 2> 1850800 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=47, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=8.6787109375, floorSegmentMB=0.560546875, forceMergeDeletesPctAllowed=29.873990069798225, segmentsPerTier=12.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1850803 WARN (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 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> 1850808 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1850808 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1850808 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1850808 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1850808 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=37, maxMergeAtOnceExplicit=43, maxMergedSegmentMB=53.3212890625, floorSegmentMB=0.85546875, forceMergeDeletesPctAllowed=27.67398114578031, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.23354800786165894
[junit4] 2> 1850809 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@72026e72[collection1] main]
[junit4] 2> 1850809 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1850810 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1850810 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1850810 INFO (searcherExecutor-8619-thread-1-processing-n:127.0.0.1:44228__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@72026e72[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1850810 INFO (coreLoadExecutor-8618-thread-1-processing-n:127.0.0.1:44228__ri%2Fz) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1548639844297605120
[junit4] 2> 1850813 INFO (coreZkRegister-8613-thread-1-processing-n:127.0.0.1:44228__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.ZkController Core needs to recover:collection1
[junit4] 2> 1850814 INFO (updateExecutor-3172-thread-1-processing-n:127.0.0.1:44228__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 1850814 INFO (recoveryExecutor-3173-thread-1-processing-n:127.0.0.1:44228__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true
[junit4] 2> 1850815 INFO (recoveryExecutor-3173-thread-1-processing-n:127.0.0.1:44228__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]]
[junit4] 2> 1850815 INFO (recoveryExecutor-3173-thread-1-processing-n:127.0.0.1:44228__ri%2Fz x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:44228__ri%2Fz c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[collection1]
[junit4] 2> 1850815 INFO (recoveryExecutor
[...truncated too long message...]
2> 1862269 WARN (Thread-4190) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 15 /solr/configs/conf1
[junit4] 2> 6 /solr/aliases.json
[junit4] 2> 5 /solr/security.json
[junit4] 2> 2 /solr/configs/.system
[junit4] 2> 2 /solr/configs/.system/managed-schema
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 6 /solr/clusterstate.json
[junit4] 2> 6 /solr/clusterprops.json
[junit4] 2> 4 /solr/collections/collection1/state.json
[junit4] 2> 2 /solr/collections/.system/state.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 33 /solr/overseer/queue
[junit4] 2> 15 /solr/overseer/queue-work
[junit4] 2> 13 /solr/overseer/collection-queue-work
[junit4] 2> 6 /solr/live_nodes
[junit4] 2> 6 /solr/collections
[junit4] 2>
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestNamedUpdateProcessors -Dtests.method=test -Dtests.seed=6CA3AF470248E8E9 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=th-TH -Dtests.timezone=Etc/GMT-7 -Dtests.asserts=true -Dtests.file.encoding=US-ASCII
[junit4] ERROR 19.1s J0 | TestNamedUpdateProcessors.test <<<
[junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at https://127.0.0.1:44228/_ri/z/collection1: error instantiating class :org.apache.solr.update.processor.RuntimeUrp
[junit4] > at __randomizedtesting.SeedInfo.seed([6CA3AF470248E8E9:E4F7909DACB48511]:0)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:593)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:262)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:251)
[junit4] > at org.apache.solr.client.solrj.SolrClient.request(SolrClient.java:1219)
[junit4] > at org.apache.solr.update.processor.TestNamedUpdateProcessors.test(TestNamedUpdateProcessors.java:125)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:992)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:967)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 1862272 INFO (SUITE-TestNamedUpdateProcessors-seed#[6CA3AF470248E8E9]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_6CA3AF470248E8E9-001
[junit4] 2> Oct 19, 2016 5:27:36 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 2 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene62): {blobName=TestBloomFilteredLucenePostings(BloomFilteringPostingsFormat(Lucene50(blocksize=128))), range_facet_l_dv=PostingsFormat(name=Memory doPackFST= false), multiDefault=TestBloomFilteredLucenePostings(BloomFilteringPostingsFormat(Lucene50(blocksize=128))), intDefault=PostingsFormat(name=LuceneVarGapDocFreqInterval), version=TestBloomFilteredLucenePostings(BloomFilteringPostingsFormat(Lucene50(blocksize=128))), mul_s=TestBloomFilteredLucenePostings(BloomFilteringPostingsFormat(Lucene50(blocksize=128))), range_facet_l=PostingsFormat(name=LuceneVarGapDocFreqInterval), test_s=PostingsFormat(name=LuceneVarGapDocFreqInterval), size=PostingsFormat(name=LuceneFixedGap), _version_=PostingsFormat(name=LuceneVarGapDocFreqInterval), id=PostingsFormat(name=Memory doPackFST= false), range_facet_i_dv=PostingsFormat(name=LuceneVarGapDocFreqInterval), md5=PostingsFormat(name=LuceneVarGapDocFreqInterval), timestamp=PostingsFormat(name=LuceneVarGapDocFreqInterval)}, docValues:{range_facet_l_dv=DocValuesFormat(name=Asserting), range_facet_i_dv=DocValuesFormat(name=Direct), timestamp=DocValuesFormat(name=Direct)}, maxPointsInLeafNode=1402, maxMBSortInHeap=7.957553748932715, sim=ClassicSimilarity, locale=th-TH, timezone=Etc/GMT-7
[junit4] 2> NOTE: Linux 4.4.0-42-generic amd64/Oracle Corporation 1.8.0_102 (64-bit)/cpus=12,threads=1,free=356799552,total=530579456
[junit4] 2> NOTE: All tests run in this JVM: [TestSearcherReuse, TestLazyCores, DistributedQueryComponentOptimizationTest, TestHdfsUpdateLog, TestRandomFaceting, TestDistributedStatsComponentCardinality, CdcrVersionReplicationTest, TestReloadAndDeleteDocs, TestManagedSchemaThreadSafety, DataDrivenBlockJoinTest, PeerSyncTest, TestTestInjection, SortSpecParsingTest, RuleEngineTest, TestSolrConfigHandlerCloud, TestSolrCloudWithKerberosAlt, HdfsRecoveryZkTest, TestHighFrequencyDictionaryFactory, TestSortingResponseWriter, DistributedVersionInfoTest, BufferStoreTest, CloudExitableDirectoryReaderTest, DirectoryFactoryTest, TestSchemaNameResource, TestExactSharedStatsCache, DistributedQueryElevationComponentTest, LeaderElectionIntegrationTest, TestRandomDVFaceting, HdfsWriteToMultipleCollectionsTest, PathHierarchyTokenizerFactoryTest, TestQueryWrapperFilter, TestSubQueryTransformerCrossCore, HdfsCollectionsAPIDistributedZkTest, HdfsThreadLeakTest, TestReplicationHandler, TestDistribDocBasedVersion, NotRequiredUniqueKeyTest, HdfsBasicDistributedZkTest, TestCollapseQParserPlugin, CdcrReplicationDistributedZkTest, DistributedDebugComponentTest, TestRemoteStreaming, TestHdfsBackupRestoreCore, TestHashQParserPlugin, TestObjectReleaseTracker, QueryResultKeyTest, ChangedSchemaMergeTest, TestMiniSolrCloudClusterSSL, TestQuerySenderNoQuery, RequestLoggingTest, TestStressRecovery, OutputWriterTest, TestRealTimeGet, JSONWriterTest, LeaderFailoverAfterPartitionTest, PreAnalyzedUpdateProcessorTest, SyncSliceTest, ClusterStateTest, TolerantUpdateProcessorTest, TestDistributedSearch, DistributedFacetPivotSmallTest, DistributedSpellCheckComponentTest, BasicDistributedZkTest, SpatialHeatmapFacetsTest, TestFunctionQuery, EnumFieldTest, TestTrackingShardHandlerFactory, LeaderInitiatedRecoveryOnShardRestartTest, TestStressUserVersions, TestOmitPositions, TestFastWriter, TestPseudoReturnFields, AnalysisAfterCoreReloadTest, TestFoldingMultitermQuery, TestSchemaVersionResource, XsltUpdateRequestHandlerTest, TestFaceting, TestLeaderInitiatedRecoveryThread, TestInfoStreamLogging, ChaosMonkeyNothingIsSafeTest, TestCrossCoreJoin, TestScoreJoinQPScore, MBeansHandlerTest, CoreAdminRequestStatusTest, UniqFieldsUpdateProcessorFactoryTest, TestEmbeddedSolrServerConstructors, TestValueSourceCache, BlockJoinFacetSimpleTest, TestPKIAuthenticationPlugin, TestFastLRUCache, TestComponentsName, TestRangeQuery, TestFieldResource, SaslZkACLProviderTest, TestDocumentBuilder, TestJmxIntegration, TestManagedSynonymFilterFactory, ConcurrentDeleteAndCreateCollectionTest, HighlighterConfigTest, TestDocTermOrds, TestSolrQueryParserResource, CollectionTooManyReplicasTest, BaseCdcrDistributedZkTest, CdcrReplicationHandlerTest, CleanupOldIndexTest, DeleteInactiveReplicaTest, DeleteNodeTest, DeleteStatusTest, DistribDocExpirationUpdateProcessorTest, LeaderFailureAfterFreshStartTest, OverseerStatusTest, OverseerTaskQueueTest, PeerSyncReplicationTest, SharedFSAutoReplicaFailoverUtilsTest, SolrCloudExampleTest, TestCloudInspectUtil, TestCloudPivotFacet, TestConfigSetsAPI, TestConfigSetsAPIExclusivity, TestExclusionRuleCollectionAccess, TestLockTree, TestMiniSolrCloudCluster, TestRequestForwarding, TestSSLRandomization, TestSizeLimitedDistributedMap, TestSolrCloudWithDelegationTokens, TestTolerantUpdateProcessorCloud, HdfsChaosMonkeyNothingIsSafeTest, HdfsChaosMonkeySafeLeaderTest, HdfsNNFailoverTest, HdfsRecoverLeaseTest, HdfsRestartWhileUpdatingTest, HdfsSyncSliceTest, HdfsTlogReplayBufferedWhileIndexingTest, TestClusterStateMutator, ZkStateReaderTest, RulesTest, TestNRTOpen, TestShardHandlerFactory, TestSolrConfigHandler, TestSolrDynamicMBean, TestBlobHandler, TestSQLHandler, DistributedQueryComponentCustomSortTest, HighlighterMaxOffsetTest, TestMacroExpander, TestMacros, TestCustomDocTransformer, TestGraphMLResponseWriter, TestRawResponseWriter, TestRawTransformer, TestChildDocTransformer, TestManagedResource, TestManagedResourceStorage, TestBulkSchemaAPI, TestCopyFieldCollectionResource, TestDefaultSearchFieldResource, TestDynamicFieldCollectionResource, TestSchemaResource, TestUniqueKeyFieldResource, SpatialRPTFieldTypeTest, TestCloudManagedSchema, TestCollationFieldDocValues, TestManagedSchema, TestManagedSchemaAPI, TestUseDocValuesAsStored, TestUseDocValuesAsStored2, AnalyticsQueryTest, CursorMarkTest, MergeStrategyTest, RankQueryTest, TestComplexPhraseQParserPlugin, TestFieldSortValues, TestGraphTermsQParserPlugin, TestInitQParser, TestMaxScoreQueryParser, TestMissingGroups, TestRandomCollapseQParserPlugin, TestMinMaxOnMultiValuedField, TestOrdValues, BJQParserTest, TestScoreJoinQPNoScore, TestJsonRequest, CloudMLTQParserTest, SimpleMLTQParserTest, TestDFISimilarityFactory, TestNonDefinedSimilarityFactory, TestPerFieldSimilarityClassic, TestDefaultStatsCache, TestDistribIDF, TestSha256AuthenticationProvider, ResponseHeaderTest, TestAnalyzeInfixSuggestions, TestBlendedInfixSuggestions, BlockCacheTest, HdfsLockFactoryTest, TestFieldCache, TestFieldCacheReopen, TestFieldCacheSanityChecker, TestFieldCacheSort, TestFieldCacheSortRandom, TestFieldCacheVsDocValues, TestFieldCacheWithThreads, TestLegacyFieldCache, TestNumericTerms32, TestNumericTerms64, IgnoreCommitOptimizeUpdateProcessorFactoryTest, ParsingFieldUpdateProcessorsTest, TestNamedUpdateProcessors]
[junit4] Completed [640/641 (1!)] on J0 in 19.86s, 1 test, 1 error <<< FAILURES!
[...truncated 60364 lines...]
[JENKINS] Lucene-Solr-6.x-Linux (64bit/jdk1.8.0_102) - Build # 1989
- Still Unstable!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Linux/1989/
Java: 64bit/jdk1.8.0_102 -XX:-UseCompressedOops -XX:+UseSerialGC
2 tests failed.
FAILED: org.apache.lucene.spatial3d.TestGeo3DPoint.testGeo3DRelations
Error Message:
invalid hits for shape=GeoRectangle: {planetmodel=PlanetModel.WGS84, toplat=0.017453291479645996(0.9999999403953552), bottomlat=-1.3962634015954636(-80.0), leftlon=2.4457272005608357E-47(1.401298464324817E-45), rightlon=1.869241958456853E-12(1.0709967510834605E-10)}
Stack Trace:
java.lang.AssertionError: invalid hits for shape=GeoRectangle: {planetmodel=PlanetModel.WGS84, toplat=0.017453291479645996(0.9999999403953552), bottomlat=-1.3962634015954636(-80.0), leftlon=2.4457272005608357E-47(1.401298464324817E-45), rightlon=1.869241958456853E-12(1.0709967510834605E-10)}
at __randomizedtesting.SeedInfo.seed([7FEDE7A41EB3B240:CF929A3091FE1CDC]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.lucene.spatial3d.TestGeo3DPoint.testGeo3DRelations(TestGeo3DPoint.java:464)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1764)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:871)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:921)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:809)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:460)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:880)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:781)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:816)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:827)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at java.lang.Thread.run(Thread.java:745)
FAILED: org.apache.solr.update.processor.TestNamedUpdateProcessors.test
Error Message:
Error from server at http://127.0.0.1:33874/collection1: error instantiating class :org.apache.solr.update.processor.RuntimeUrp
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:33874/collection1: error instantiating class :org.apache.solr.update.processor.RuntimeUrp
at __randomizedtesting.SeedInfo.seed([EA74867045368D8C:6220B9AAEBCAE074]:0)
at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:593)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:262)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:251)
at org.apache.solr.client.solrj.SolrClient.request(SolrClient.java:1219)
at org.apache.solr.update.processor.TestNamedUpdateProcessors.test(TestNamedUpdateProcessors.java:125)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1764)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:871)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:921)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:992)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:967)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:809)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:460)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:880)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:781)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:816)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:827)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 9043 lines...]
[junit4] Suite: org.apache.lucene.spatial3d.TestGeo3DPoint
[junit4] IGNOR/A 0.01s J1 | TestGeo3DPoint.testRandomBig
[junit4] > Assumption #1: 'nightly' test group is disabled (@Nightly())
[junit4] 1> doc=23 should match but did not
[junit4] 1> point=[X=-0.3032237416849336, Y=2.3309121299774915E-10, Z=-0.9508945608073219]
[junit4] 1> mappedPoint=[lat=-1.2621073061661279, lon=3.141592653589793([X=-0.3032237417663322, Y=3.7134198477962236E-17, Z=-0.9508945610068391])]
[junit4] 1> doc=30 should match but did not
[junit4] 1> point=[X=-0.19482888783564378, Y=2.3309121299774915E-10, Z=-0.9786855487622393]
[junit4] 1> mappedPoint=[lat=-1.3742932353673953, lon=3.141592653589793([X=-0.1948288878124478, Y=2.3859657384095297E-17, Z=-0.9786855486360273])]
[junit4] 1> doc=83 should match but did not
[junit4] 1> point=[X=-0.2892999513665818, Y=2.3309121299774915E-10, Z=-0.9551939133132278]
[junit4] 1> mappedPoint=[lat=-1.2767082336466407, lon=3.141592653589793([X=-0.2892999511883776, Y=3.5429025921633215E-17, Z=-0.9551939133776381])]
[junit4] 1> doc=204 should match but did not
[junit4] 1> point=[X=-0.2304883857492458, Y=-2.3309121299774915E-10, Z=-0.970958461302852]
[junit4] 1> mappedPoint=[lat=-1.3377279126209909, lon=-3.141592653589793([X=-0.23048838553642823, Y=-2.8226686358782794E-17, Z=-0.9709584613946622])]
[junit4] 1> doc=295 should match but did not
[junit4] 1> point=[X=-0.38044050228897974, Y=2.3309121299774915E-10, Z=-0.9229103565532143]
[junit4] 1> mappedPoint=[lat=-1.1798015420947494, lon=3.141592653589793([X=-0.38044050220203357, Y=4.6590524328773195E-17, Z=-0.9229103567469498])]
[junit4] 1> doc=335 should match but did not
[junit4] 1> point=[X=-0.34552679276447196, Y=-2.3309121299774915E-10, Z=-0.9364507784902717]
[junit4] 1> mappedPoint=[lat=-1.2173184081667363, lon=-3.141592653589793([X=-0.3455267925813584, Y=-4.2314828055441195E-17, Z=-0.9364507786023997])]
[junit4] 1> doc=444 should match but did not
[junit4] 1> point=[X=-0.35565273191587166, Y=2.3309121299774915E-10, Z=-0.9326775916369318]
[junit4] 1> mappedPoint=[lat=-1.2064925301928429, lon=3.141592653589793([X=-0.35565273187036933, Y=4.355489796930597E-17, Z=-0.9326775917892445])]
[junit4] 1> doc=456 should match but did not
[junit4] 1> point=[X=-0.24059621278103072, Y=2.3309121299774915E-10, Z=-0.9685197822476396]
[junit4] 1> mappedPoint=[lat=-1.3273086505286442, lon=3.141592653589793([X=-0.24059621266986583, Y=2.9464538173312706E-17, Z=-0.9685197820947206])]
[junit4] 1> doc=749 should match but did not
[junit4] 1> point=[X=-0.27931563097728074, Y=2.3309121299774915E-10, Z=-0.9581412458781736]
[junit4] 1> mappedPoint=[lat=-1.2871390311991375, lon=3.141592653589793([X=-0.27931563076181104, Y=3.420629931642758E-17, Z=-0.9581412457046323])]
[junit4] 1> doc=978 should match but did not
[junit4] 1> point=[X=-0.20014590305820745, Y=-2.3309121299774915E-10, Z=-0.9776192380446992]
[junit4] 1> mappedPoint=[lat=-1.3688589001639526, lon=-3.141592653589793([X=-0.20014590297436863, Y=-2.4510803944001724E-17, Z=-0.9776192382200114])]
[junit4] 1> doc=1019 should match but did not
[junit4] 1> point=[X=-0.1895701514767011, Y=-2.3309121299774915E-10, Z=-0.9797108368248392]
[junit4] 1> mappedPoint=[lat=-1.3796623403968673, lon=-3.141592653589793([X=-0.18957015125823026, Y=-2.3215647895227127E-17, Z=-0.9797108369364872])]
[junit4] 1> doc=1050 should match but did not
[junit4] 1> point=[X=-0.37669388969865125, Y=-2.3309121299774915E-10, Z=-0.9244356257338767]
[junit4] 1> mappedPoint=[lat=-1.1838538424170673, lon=-3.141592653589793([X=-0.37669388956862926, Y=-4.613169661185884E-17, Z=-0.9244356256615374])]
[junit4] 1> doc=1077 should match but did not
[junit4] 1> point=[X=-0.281464835919801, Y=-2.3309121299774915E-10, Z=-0.9575163092226472]
[junit4] 1> mappedPoint=[lat=-1.2848963877296418, lon=-3.141592653589793([X=-0.2814648357291603, Y=-3.4469501014825175E-17, Z=-0.957516309437251])]
[junit4] 1> doc=1087 should match but did not
[junit4] 1> point=[X=-0.22993880934761124, Y=-2.3309121299774915E-10, Z=-0.9710878847326866]
[junit4] 1> mappedPoint=[lat=-1.3382936874912785, lon=-3.141592653589793([X=-0.22993880922160065, Y=-2.8159382671298716E-17, Z=-0.9710878846374904])]
[junit4] 1> doc=1245 should match but did not
[junit4] 1> point=[X=-0.2977325835509569, Y=-2.3309121299774915E-10, Z=-0.9526165659644908]
[junit4] 1> mappedPoint=[lat=-1.2678732944040285, lon=-3.141592653589793([X=-0.2977325833240384, Y=-3.6461725516965625E-17, Z=-0.9526165658097825])]
[junit4] 1> doc=1274 should match but did not
[junit4] 1> point=[X=-0.2230123351953449, Y=-2.3309121299774915E-10, Z=-0.9726911285182859]
[junit4] 1> mappedPoint=[lat=-1.345418012127493, lon=-3.141592653589793([X=-0.2230123354014425, Y=-2.7311134271975252E-17, Z=-0.9726911284129601])]
[junit4] 1> doc=1365 should match but did not
[junit4] 1> point=[X=-0.21337764463280406, Y=-2.3309121299774915E-10, Z=-0.9748355592865815]
[junit4] 1> mappedPoint=[lat=-1.3553090486591461, lon=-3.141592653589793([X=-0.21337764449242597, Y=-2.6131224933725133E-17, Z=-0.9748355591900344])]
[junit4] 1> doc=1421 should match but did not
[junit4] 1> point=[X=-0.357719833275708, Y=-2.3309121299774915E-10, Z=-0.9318920262323395]
[junit4] 1> mappedPoint=[lat=-1.2042771838760873, lon=-3.141592653589793([X=-0.3577198333651691, Y=-4.380804489221789E-17, Z=-0.9318920261236907])]
[junit4] 1> doc=1567 should match but did not
[junit4] 1> point=[X=-0.2019549943558293, Y=2.3309121299774915E-10, Z=-0.977249613653688]
[junit4] 1> mappedPoint=[lat=-1.367008546421418, lon=3.141592653589793([X=-0.2019549945354198, Y=2.4732353762962308E-17, Z=-0.9772496136297395])]
[junit4] 1> doc=1695 should match but did not
[junit4] 1> point=[X=-0.21798690729041048, Y=-2.3309121299774915E-10, Z=-0.9738220605113527]
[junit4] 1> mappedPoint=[lat=-1.3505798311224506, lon=-3.141592653589793([X=-0.2179869073694118, Y=-2.6695696836598075E-17, Z=-0.9738220602853552])]
[junit4] 1> doc=1858 should match but did not
[junit4] 1> point=[X=-0.2881195858552449, Y=2.3309121299774915E-10, Z=-0.9555482278071868]
[junit4] 1> mappedPoint=[lat=-1.2779430458945407, lon=3.141592653589793([X=-0.2881195859095498, Y=3.5284472865579097E-17, Z=-0.9555482277022879])]
[junit4] 1> doc=2207 should match but did not
[junit4] 1> point=[X=-0.32595903903655066, Y=-2.3309121299774915E-10, Z=-0.9433936450151833]
[junit4] 1> mappedPoint=[lat=-1.2381203695374021, lon=-3.141592653589793([X=-0.3259590392236278, Y=-3.991846940383623E-17, Z=-0.9433936449254461])]
[junit4] 1> doc=2349 should match but did not
[junit4] 1> point=[X=-0.20974591943808518, Y=-2.3309121299774915E-10, Z=-0.9756181369280056]
[junit4] 1> mappedPoint=[lat=-1.3590319035018428, lon=-3.141592653589793([X=-0.20974591957164881, Y=-2.5686466903763788E-17, Z=-0.9756181367786224])]
[junit4] 1> doc=2380 should match but did not
[junit4] 1> point=[X=-0.4875463924984321, Y=2.3309121299774915E-10, Z=-0.8714467112499943]
[junit4] 1> mappedPoint=[lat=-1.06071322725801, lon=3.141592653589793([X=-0.48754639238198005, Y=5.970721288664315E-17, Z=-0.8714467113481478])]
[junit4] 1> doc=2403 should match but did not
[junit4] 1> point=[X=-0.5307326574182415, Y=2.3309121299774915E-10, Z=-0.8460130563140477]
[junit4] 1> mappedPoint=[lat=-1.0105204721369465, lon=3.141592653589793([X=-0.5307326575599536, Y=6.499600502837654E-17, Z=-0.8460130563310785])]
[junit4] 1> doc=2647 should match but did not
[junit4] 1> point=[X=-0.41216428024496576, Y=-2.3309121299774915E-10, Z=-0.9092785241675204]
[junit4] 1> mappedPoint=[lat=-1.1452121604915835, lon=-3.141592653589793([X=-0.41216428042536374, Y=-5.047556667457938E-17, Z=-0.9092785241822108])]
[junit4] 1> doc=2672 should match but did not
[junit4] 1> point=[X=-0.18909431254793352, Y=-2.3309121299774915E-10, Z=-0.9798021745490172]
[junit4] 1> mappedPoint=[lat=-1.380147893716371, lon=-3.141592653589793([X=-0.18909431255244671, Y=-2.3157374460432306E-17, Z=-0.9798021744231401])]
[junit4] 1> doc=2676 should match but did not
[junit4] 1> point=[X=-0.2859003155588272, Y=-2.3309121299774915E-10, Z=-0.9562101196759868]
[junit4] 1> mappedPoint=[lat=-1.2802634653663008, lon=-3.141592653589793([X=-0.2859003156392869, Y=-3.501269064228707E-17, Z=-0.9562101195662314])]
[junit4] 1> doc=2682 should match but did not
[junit4] 1> point=[X=-0.5068398365617964, Y=-2.3309121299774915E-10, Z=-0.86044329743017]
[junit4] 1> mappedPoint=[lat=-1.038470904936626, lon=-3.141592653589793([X=-0.5068398363428848, Y=-6.206997832576823E-17, Z=-0.8604432975645862])]
[junit4] 1> doc=2784 should match but did not
[junit4] 1> point=[X=-0.37840497686340335, Y=-2.3309121299774915E-10, Z=-0.9237412167084987]
[junit4] 1> mappedPoint=[lat=-1.1820039671839628, lon=-3.141592653589793([X=-0.37840497689182123, Y=-4.6341244373199705E-17, Z=-0.92374121663021])]
[junit4] 1> doc=2880 should match but did not
[junit4] 1> point=[X=-0.2569863542772196, Y=-2.3309121299774915E-10, Z=-0.9643286344122667]
[junit4] 1> mappedPoint=[lat=-1.3103565403065773, lon=-3.141592653589793([X=-0.25698635432302114, Y=-3.1471751624623544E-17, Z=-0.9643286344522917])]
[junit4] 1> doc=2902 should match but did not
[junit4] 1> point=[X=-0.5314576316943799, Y=-2.3309121299774915E-10, Z=-0.8455608705492103]
[junit4] 1> mappedPoint=[lat=-1.0096649353953517, lon=-3.141592653589793([X=-0.5314576318897689, Y=-6.508478877762378E-17, Z=-0.8455608705872797])]
[junit4] 1> doc=2961 should match but did not
[junit4] 1> point=[X=-0.22611501186537553, Y=-2.3309121299774915E-10, Z=-0.9719793532651747]
[junit4] 1> mappedPoint=[lat=-1.3422281433038927, lon=-3.141592653589793([X=-0.2261150116836731, Y=-2.7691102529757665E-17, Z=-0.9719793532388703])]
[junit4] 1> doc=3060 should match but did not
[junit4] 1> point=[X=-0.3694237626445084, Y=2.3309121299774915E-10, Z=-0.9273452879617076]
[junit4] 1> mappedPoint=[lat=-1.1916984985376446, lon=3.141592653589793([X=-0.36942376251911235, Y=4.524136282980029E-17, Z=-0.9273452880788157])]
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestGeo3DPoint -Dtests.method=testGeo3DRelations -Dtests.seed=7FEDE7A41EB3B240 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=en-IE -Dtests.timezone=America/St_Kitts -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] FAILURE 0.21s J1 | TestGeo3DPoint.testGeo3DRelations <<<
[junit4] > Throwable #1: java.lang.AssertionError: invalid hits for shape=GeoRectangle: {planetmodel=PlanetModel.WGS84, toplat=0.017453291479645996(0.9999999403953552), bottomlat=-1.3962634015954636(-80.0), leftlon=2.4457272005608357E-47(1.401298464324817E-45), rightlon=1.869241958456853E-12(1.0709967510834605E-10)}
[junit4] > at __randomizedtesting.SeedInfo.seed([7FEDE7A41EB3B240:CF929A3091FE1CDC]:0)
[junit4] > at org.apache.lucene.spatial3d.TestGeo3DPoint.testGeo3DRelations(TestGeo3DPoint.java:464)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene62): {id=PostingsFormat(name=LuceneFixedGap)}, docValues:{id=DocValuesFormat(name=Lucene54), point=DocValuesFormat(name=Direct)}, maxPointsInLeafNode=1896, maxMBSortInHeap=5.304289065936136, sim=RandomSimilarity(queryNorm=true,coord=crazy): {}, locale=en-IE, timezone=America/St_Kitts
[junit4] 2> NOTE: Linux 4.4.0-42-generic amd64/Oracle Corporation 1.8.0_102 (64-bit)/cpus=12,threads=1,free=452209936,total=508887040
[junit4] 2> NOTE: All tests run in this JVM: [TestGeo3DPoint]
[junit4] Completed [10/11 (1!)] on J1 in 68.45s, 14 tests, 1 failure, 1 skipped <<< FAILURES!
[...truncated 3662 lines...]
[junit4] Suite: org.apache.solr.update.processor.TestNamedUpdateProcessors
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/init-core-data-001
[junit4] 2> 1878885 INFO (SUITE-TestNamedUpdateProcessors-seed#[EA74867045368D8C]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
[junit4] 2> 1878885 INFO (SUITE-TestNamedUpdateProcessors-seed#[EA74867045368D8C]-worker) [ ] o.a.s.BaseDistributedSearchTestCase Setting hostContext system property: /
[junit4] 2> 1878886 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 1878886 INFO (Thread-3955) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1878886 INFO (Thread-3955) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 1878986 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.ZkTestServer start zk server on port:33839
[junit4] 2> 1878993 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 1878994 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4] 2> 1878994 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 1878995 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 1878995 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 1878996 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4] 2> 1878996 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml
[junit4] 2> 1878996 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 1878997 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 1878997 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 1878998 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 1879045 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/control-001/cores/collection1
[junit4] 2> 1879046 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1879046 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@75276d87{/,null,AVAILABLE}
[junit4] 2> 1879047 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.ServerConnector Started ServerConnector@7fdf2982{HTTP/1.1,[http/1.1]}{127.0.0.1:38997}
[junit4] 2> 1879047 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.Server Started @1880831ms
[junit4] 2> 1879047 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/tempDir-001/control/data, hostContext=/, hostPort=38997, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/control-001/cores}
[junit4] 2> 1879047 ERROR (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1879047 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.3.0
[junit4] 2> 1879047 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1879047 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1879047 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-10-19T20:41:27.905Z
[junit4] 2> 1879048 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1879049 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/control-001/solr.xml
[junit4] 2> 1879052 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1879053 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:33839/solr
[junit4] 2> 1879059 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:38997_ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:38997_
[junit4] 2> 1879060 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:38997_ ] o.a.s.c.Overseer Overseer (id=96790753296056324-127.0.0.1:38997_-n_0000000000) starting
[junit4] 2> 1879061 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:38997_ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38997_
[junit4] 2> 1879062 INFO (zkCallback-2734-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1879070 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:38997_ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/control-001/cores
[junit4] 2> 1879070 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:38997_ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1879071 INFO (OverseerStateUpdate-96790753296056324-127.0.0.1:38997_-n_0000000000) [n:127.0.0.1:38997_ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 1880079 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ c:control_collection x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1880091 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ c:control_collection x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1880177 WARN (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ 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> 1880179 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ c:control_collection x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 1880183 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ c:control_collection x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection control_collection
[junit4] 2> 1880184 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/control-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/control-001/cores/collection1/data/]
[junit4] 2> 1880184 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ 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@271a4ce9
[junit4] 2> 1880184 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ 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=48, maxMergeAtOnceExplicit=48, maxMergedSegmentMB=37.7001953125, floorSegmentMB=2.0224609375, forceMergeDeletesPctAllowed=14.243584977913203, segmentsPerTier=44.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.2563481710049721
[junit4] 2> 1880187 WARN (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ 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> 1880191 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ 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> 1880191 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ 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> 1880192 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1880192 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1880192 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ 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=42, maxMergeAtOnceExplicit=37, maxMergedSegmentMB=16.4169921875, floorSegmentMB=1.99609375, forceMergeDeletesPctAllowed=25.25940108286577, segmentsPerTier=16.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.18976930808205347
[junit4] 2> 1880192 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@229f2a24[collection1] main]
[junit4] 2> 1880193 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1880193 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ 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> 1880193 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1880193 INFO (searcherExecutor-7738-thread-1-processing-n:127.0.0.1:38997_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@229f2a24[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1880193 INFO (coreLoadExecutor-7737-thread-1-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ 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 1548652054106341376
[junit4] 2> 1880197 INFO (coreZkRegister-7730-thread-1-processing-n:127.0.0.1:38997_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1880197 INFO (coreZkRegister-7730-thread-1-processing-n:127.0.0.1:38997_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:38997_ 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> 1880197 INFO (coreZkRegister-7730-thread-1-processing-n:127.0.0.1:38997_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:38997/collection1/
[junit4] 2> 1880197 INFO (coreZkRegister-7730-thread-1-processing-n:127.0.0.1:38997_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1880197 INFO (coreZkRegister-7730-thread-1-processing-n:127.0.0.1:38997_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy http://127.0.0.1:38997/collection1/ has no replicas
[junit4] 2> 1880198 INFO (coreZkRegister-7730-thread-1-processing-n:127.0.0.1:38997_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:38997_ 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:38997/collection1/ shard1
[junit4] 2> 1880349 INFO (coreZkRegister-7730-thread-1-processing-n:127.0.0.1:38997_ x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:38997_ c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1880573 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1880574 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.ChaosMonkey monkey: init - expire sessions:false cause connection loss:false
[junit4] 2> 1880574 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractFullDistribZkTestBase Creating collection1 with stateFormat=2
[junit4] 2> 1880628 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-1-001/cores/collection1
[junit4] 2> 1880628 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 1 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-1-001
[junit4] 2> 1880628 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1880629 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@6b5e0e6f{/,null,AVAILABLE}
[junit4] 2> 1880629 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.ServerConnector Started ServerConnector@628abe4c{HTTP/1.1,[http/1.1]}{127.0.0.1:41769}
[junit4] 2> 1880629 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.Server Started @1882414ms
[junit4] 2> 1880629 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/tempDir-001/jetty1, solrconfig=solrconfig.xml, hostContext=/, hostPort=41769, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-1-001/cores}
[junit4] 2> 1880629 ERROR (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1880630 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.3.0
[junit4] 2> 1880630 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1880630 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1880630 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-10-19T20:41:29.488Z
[junit4] 2> 1880631 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1880631 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-1-001/solr.xml
[junit4] 2> 1880635 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1880636 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:33839/solr
[junit4] 2> 1880640 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:41769_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1880641 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:41769_ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41769_
[junit4] 2> 1880642 INFO (zkCallback-2734-thread-2-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1880643 INFO (zkCallback-2738-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1880643 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1880656 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:41769_ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-1-001/cores
[junit4] 2> 1880656 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:41769_ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1880658 INFO (OverseerStateUpdate-96790753296056324-127.0.0.1:38997_-n_0000000000) [n:127.0.0.1:38997_ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 1880759 WARN (OverseerStateUpdate-96790753296056324-127.0.0.1:38997_-n_0000000000) [n:127.0.0.1:38997_ ] o.a.s.c.Overseer Bad version writing to ZK using compare-and-set, will force refresh cluster state: KeeperErrorCode = BadVersion for /collections/collection1/state.json
[junit4] 2> 1880760 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] 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> 1880761 INFO (OverseerStateUpdate-96790753296056324-127.0.0.1:38997_-n_0000000000) [n:127.0.0.1:38997_ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 1880761 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] 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> 1881666 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1881692 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1881770 WARN (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ 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> 1881771 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 1881776 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1
[junit4] 2> 1881776 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-1-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-1-001/cores/collection1/data/]
[junit4] 2> 1881776 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 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@271a4ce9
[junit4] 2> 1881777 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=48, maxMergeAtOnceExplicit=48, maxMergedSegmentMB=37.7001953125, floorSegmentMB=2.0224609375, forceMergeDeletesPctAllowed=14.243584977913203, segmentsPerTier=44.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.2563481710049721
[junit4] 2> 1881780 WARN (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 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> 1881785 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1881785 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1881785 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1881785 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1881786 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=42, maxMergeAtOnceExplicit=37, maxMergedSegmentMB=16.4169921875, floorSegmentMB=1.99609375, forceMergeDeletesPctAllowed=25.25940108286577, segmentsPerTier=16.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.18976930808205347
[junit4] 2> 1881786 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@28c4f5e6[collection1] main]
[junit4] 2> 1881787 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1881787 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1881787 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1881788 INFO (searcherExecutor-7749-thread-1-processing-n:127.0.0.1:41769_ x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@28c4f5e6[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1881788 INFO (coreLoadExecutor-7748-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1548652055778820096
[junit4] 2> 1881792 INFO (coreZkRegister-7743-thread-1-processing-n:127.0.0.1:41769_ x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1881792 INFO (coreZkRegister-7743-thread-1-processing-n:127.0.0.1:41769_ x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1881792 INFO (coreZkRegister-7743-thread-1-processing-n:127.0.0.1:41769_ x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:41769/collection1/
[junit4] 2> 1881792 INFO (coreZkRegister-7743-thread-1-processing-n:127.0.0.1:41769_ x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1881792 INFO (coreZkRegister-7743-thread-1-processing-n:127.0.0.1:41769_ x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SyncStrategy http://127.0.0.1:41769/collection1/ has no replicas
[junit4] 2> 1881793 INFO (coreZkRegister-7743-thread-1-processing-n:127.0.0.1:41769_ x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:41769/collection1/ shard2
[junit4] 2> 1881895 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] 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> 1881944 INFO (coreZkRegister-7743-thread-1-processing-n:127.0.0.1:41769_ x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:41769_ c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1882045 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] 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> 1882218 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-2-001/cores/collection1
[junit4] 2> 1882218 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 2 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-2-001
[junit4] 2> 1882219 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1882220 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@251b1bc7{/,null,AVAILABLE}
[junit4] 2> 1882220 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.ServerConnector Started ServerConnector@717b8e21{HTTP/1.1,[http/1.1]}{127.0.0.1:33874}
[junit4] 2> 1882220 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.Server Started @1884005ms
[junit4] 2> 1882220 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/tempDir-001/jetty2, solrconfig=solrconfig.xml, hostContext=/, hostPort=33874, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-2-001/cores}
[junit4] 2> 1882220 ERROR (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1882220 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.3.0
[junit4] 2> 1882220 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1882220 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1882220 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-10-19T20:41:31.078Z
[junit4] 2> 1882222 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1882222 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-2-001/solr.xml
[junit4] 2> 1882227 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1882227 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:33839/solr
[junit4] 2> 1882232 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:33874_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 1882234 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:33874_ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33874_
[junit4] 2> 1882235 INFO (zkCallback-2750-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1882235 INFO (zkCallback-2734-thread-2-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1882235 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1882235 INFO (zkCallback-2738-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 1882242 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:33874_ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-2-001/cores
[junit4] 2> 1882242 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:33874_ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1882244 INFO (OverseerStateUpdate-96790753296056324-127.0.0.1:38997_-n_0000000000) [n:127.0.0.1:38997_ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 1882345 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] 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> 1882345 INFO (zkCallback-2750-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ ] 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> 1883252 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1883279 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1883358 WARN (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ 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> 1883360 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 1883365 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1
[junit4] 2> 1883365 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-2-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-2-001/cores/collection1/data/]
[junit4] 2> 1883365 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ 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@271a4ce9
[junit4] 2> 1883366 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=48, maxMergeAtOnceExplicit=48, maxMergedSegmentMB=37.7001953125, floorSegmentMB=2.0224609375, forceMergeDeletesPctAllowed=14.243584977913203, segmentsPerTier=44.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.2563481710049721
[junit4] 2> 1883368 WARN (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ 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> 1883374 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1883374 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ 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> 1883374 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1883374 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1883376 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=42, maxMergeAtOnceExplicit=37, maxMergedSegmentMB=16.4169921875, floorSegmentMB=1.99609375, forceMergeDeletesPctAllowed=25.25940108286577, segmentsPerTier=16.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.18976930808205347
[junit4] 2> 1883376 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@58894fe9[collection1] main]
[junit4] 2> 1883377 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1883377 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ 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> 1883377 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1883378 INFO (searcherExecutor-7760-thread-1-processing-n:127.0.0.1:33874_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@58894fe9[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1883378 INFO (coreLoadExecutor-7759-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ 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 1548652057446055936
[junit4] 2> 1883381 INFO (coreZkRegister-7754-thread-1-processing-n:127.0.0.1:33874_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1883381 INFO (coreZkRegister-7754-thread-1-processing-n:127.0.0.1:33874_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1883381 INFO (coreZkRegister-7754-thread-1-processing-n:127.0.0.1:33874_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:33874/collection1/
[junit4] 2> 1883381 INFO (coreZkRegister-7754-thread-1-processing-n:127.0.0.1:33874_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1883381 INFO (coreZkRegister-7754-thread-1-processing-n:127.0.0.1:33874_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SyncStrategy http://127.0.0.1:33874/collection1/ has no replicas
[junit4] 2> 1883382 INFO (coreZkRegister-7754-thread-1-processing-n:127.0.0.1:33874_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:33874/collection1/ shard1
[junit4] 2> 1883483 INFO (zkCallback-2750-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ ] 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> 1883483 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] 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> 1883533 INFO (coreZkRegister-7754-thread-1-processing-n:127.0.0.1:33874_ x:collection1 s:shard1 c:collection1 r:core_node2) [n:127.0.0.1:33874_ c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1883635 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] 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> 1883635 INFO (zkCallback-2750-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ ] 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> 1883792 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-3-001/cores/collection1
[junit4] 2> 1883793 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 3 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-3-001
[junit4] 2> 1883793 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1883794 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@7f8dc0ec{/,null,AVAILABLE}
[junit4] 2> 1883794 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.ServerConnector Started ServerConnector@2a7f2f0f{HTTP/1.1,[http/1.1]}{127.0.0.1:34024}
[junit4] 2> 1883794 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.Server Started @1885579ms
[junit4] 2> 1883794 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/tempDir-001/jetty3, solrconfig=solrconfig.xml, hostContext=/, hostPort=34024, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-3-001/cores}
[junit4] 2> 1883794 ERROR (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1883795 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.3.0
[junit4] 2> 1883795 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1883795 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1883795 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-10-19T20:41:32.653Z
[junit4] 2> 1883797 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 1883797 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-3-001/solr.xml
[junit4] 2> 1883801 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1883802 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:33839/solr
[junit4] 2> 1883806 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:34024_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3)
[junit4] 2> 1883808 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:34024_ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34024_
[junit4] 2> 1883825 INFO (zkCallback-2738-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 1883825 INFO (zkCallback-2756-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 1883826 INFO (zkCallback-2750-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 1883826 INFO (zkCallback-2734-thread-2-processing-n:127.0.0.1:38997_) [n:127.0.0.1:38997_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 1883826 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 1883836 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:34024_ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-3-001/cores
[junit4] 2> 1883836 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [n:127.0.0.1:34024_ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1883837 INFO (OverseerStateUpdate-96790753296056324-127.0.0.1:38997_-n_0000000000) [n:127.0.0.1:38997_ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 1883939 INFO (zkCallback-2756-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ ] 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: [4])
[junit4] 2> 1883939 INFO (zkCallback-2750-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ ] 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: [4])
[junit4] 2> 1883939 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] 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: [4])
[junit4] 2> 1884846 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.3.0
[junit4] 2> 1884858 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1884939 WARN (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ 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> 1884941 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 1884946 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1
[junit4] 2> 1884946 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-3-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-3-001/cores/collection1/data/]
[junit4] 2> 1884946 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@271a4ce9
[junit4] 2> 1884947 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=48, maxMergeAtOnceExplicit=48, maxMergedSegmentMB=37.7001953125, floorSegmentMB=2.0224609375, forceMergeDeletesPctAllowed=14.243584977913203, segmentsPerTier=44.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.2563481710049721
[junit4] 2> 1884949 WARN (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 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> 1884955 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1884955 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1884956 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1884956 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1884957 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=42, maxMergeAtOnceExplicit=37, maxMergedSegmentMB=16.4169921875, floorSegmentMB=1.99609375, forceMergeDeletesPctAllowed=25.25940108286577, segmentsPerTier=16.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.18976930808205347
[junit4] 2> 1884957 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@496e67a2[collection1] main]
[junit4] 2> 1884971 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1884971 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1884971 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1884972 INFO (searcherExecutor-7771-thread-1-processing-n:127.0.0.1:34024_ x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@496e67a2[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1884972 INFO (coreLoadExecutor-7770-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1548652059117486080
[junit4] 2> 1884974 INFO (coreZkRegister-7765-thread-1-processing-n:127.0.0.1:34024_ x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.ZkController Core needs to recover:collection1
[junit4] 2> 1884975 INFO (updateExecutor-2753-thread-1-processing-n:127.0.0.1:34024_ x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 1884975 INFO (recoveryExecutor-2754-thread-1-processing-n:127.0.0.1:34024_ x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true
[junit4] 2> 1884976 INFO (recoveryExecutor-2754-thread-1-processing-n:127.0.0.1:34024_ x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]]
[junit4] 2> 1884976 INFO (recoveryExecutor-2754-thread-1-processing-n:127.0.0.1:34024_ x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[collection1]
[junit4] 2> 1884976 INFO (recoveryExecutor-2754-thread-1-processing-n:127.0.0.1:34024_ x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 1884976 INFO (recoveryExecutor-2754-thread-1-processing-n:127.0.0.1:34024_ x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Publishing state of core [collection1] as recovering, leader is [http://127.0.0.1:41769/collection1/] and I am [http://127.0.0.1:34024/collection1/]
[junit4] 2> 1884977 INFO (recoveryExecutor-2754-thread-1-processing-n:127.0.0.1:34024_ x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:34024_ c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:41769]; [WaitForState: action=PREPRECOVERY&core=collection1&nodeName=127.0.0.1:34024_&coreNodeName=core_node3&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
[junit4] 2> 1884978 INFO (qtp764128638-15774) [n:127.0.0.1:41769_ ] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true
[junit4] 2> 1884978 INFO (qtp764128638-15774) [n:127.0.0.1:41769_ ] o.a.s.h.a.PrepRecoveryOp Will wait a max of 183 seconds to see collection1 (shard2 of collection1) have state: recovering
[junit4] 2> 1884978 INFO (qtp764128638-15774) [n:127.0.0.1:41769_ ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard2, thisCore=collection1, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:34024_, coreNodeName=core_node3, onlyIfActiveCheckResult=false, nodeProps: core_node3:{"core":"collection1","base_url":"http://127.0.0.1:34024","node_name":"127.0.0.1:34024_","state":"down"}
[junit4] 2> 1885078 INFO (zkCallback-2756-thread-1-processing-n:127.0.0.1:34024_) [n:127.0.0.1:34024_ ] 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: [4])
[junit4] 2> 1885078 INFO (zkCallback-2744-thread-1-processing-n:127.0.0.1:41769_) [n:127.0.0.1:41769_ ] 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: [4])
[junit4] 2> 1885078 INFO (zkCallback-2750-thread-1-processing-n:127.0.0.1:33874_) [n:127.0.0.1:33874_ ] 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: [4])
[junit4] 2> 1885406 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-4-001/cores/collection1
[junit4] 2> 1885406 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 4 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-4-001
[junit4] 2> 1885407 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
[junit4] 2> 1885408 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@76547b1d{/,null,AVAILABLE}
[junit4] 2> 1885408 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.ServerConnector Started ServerConnector@1a61c58{HTTP/1.1,[http/1.1]}{127.0.0.1:38830}
[junit4] 2> 1885408 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.Server Started @1887193ms
[junit4] 2> 1885408 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/tempDir-001/jetty4, solrconfig=solrconfig.xml, hostContext=/, hostPort=38830, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001/shard-4-001/cores}
[junit4] 2> 1885408 ERROR (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 18
[...truncated too long message...]
) [ ] o.e.j.s.ServerConnector Stopped ServerConnector@1a61c58{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1900268 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@76547b1d{/,null,UNAVAILABLE}
[junit4] 2> 1900269 INFO (TEST-TestNamedUpdateProcessors.test-seed#[EA74867045368D8C]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:33839 33839
[junit4] 2> 1900372 INFO (Thread-3955) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:33839 33839
[junit4] 2> 1900372 WARN (Thread-3955) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 15 /solr/configs/conf1
[junit4] 2> 6 /solr/aliases.json
[junit4] 2> 6 /solr/clusterprops.json
[junit4] 2> 5 /solr/security.json
[junit4] 2> 2 /solr/configs/.system
[junit4] 2> 2 /solr/configs/.system/managed-schema
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 6 /solr/clusterstate.json
[junit4] 2> 4 /solr/collections/collection1/state.json
[junit4] 2> 2 /solr/collections/.system/state.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 38 /solr/overseer/queue
[junit4] 2> 18 /solr/overseer/queue-work
[junit4] 2> 13 /solr/overseer/collection-queue-work
[junit4] 2> 6 /solr/live_nodes
[junit4] 2> 6 /solr/collections
[junit4] 2>
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestNamedUpdateProcessors -Dtests.method=test -Dtests.seed=EA74867045368D8C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ko -Dtests.timezone=Africa/Maseru -Dtests.asserts=true -Dtests.file.encoding=US-ASCII
[junit4] ERROR 21.5s J0 | TestNamedUpdateProcessors.test <<<
[junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:33874/collection1: error instantiating class :org.apache.solr.update.processor.RuntimeUrp
[junit4] > at __randomizedtesting.SeedInfo.seed([EA74867045368D8C:6220B9AAEBCAE074]:0)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:593)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:262)
[junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:251)
[junit4] > at org.apache.solr.client.solrj.SolrClient.request(SolrClient.java:1219)
[junit4] > at org.apache.solr.update.processor.TestNamedUpdateProcessors.test(TestNamedUpdateProcessors.java:125)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:992)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:967)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 1900375 INFO (SUITE-TestNamedUpdateProcessors-seed#[EA74867045368D8C]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.processor.TestNamedUpdateProcessors_EA74867045368D8C-001
[junit4] 2> Oct 19, 2016 8:41:49 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): {blobName=FST50, range_facet_l_dv=PostingsFormat(name=Asserting), multiDefault=FST50, intDefault=Lucene50(blocksize=128), version=Lucene50(blocksize=128), mul_s=Lucene50(blocksize=128), range_facet_l=FST50, test_s=Lucene50(blocksize=128), size=PostingsFormat(name=Direct), _version_=Lucene50(blocksize=128), id=PostingsFormat(name=Asserting), range_facet_i_dv=FST50, md5=FST50, timestamp=FST50}, docValues:{range_facet_l_dv=DocValuesFormat(name=Lucene54), range_facet_i_dv=DocValuesFormat(name=Memory), timestamp=DocValuesFormat(name=Memory)}, maxPointsInLeafNode=93, maxMBSortInHeap=7.211972473299859, sim=RandomSimilarity(queryNorm=false,coord=yes): {}, locale=ko, timezone=Africa/Maseru
[junit4] 2> NOTE: Linux 4.4.0-42-generic amd64/Oracle Corporation 1.8.0_102 (64-bit)/cpus=12,threads=1,free=151161536,total=518979584
[junit4] 2> NOTE: All tests run in this JVM: [TestCollapseQParserPlugin, TestShortCircuitedRequests, TestTolerantUpdateProcessorCloud, TestConfigSetsAPIExclusivity, TestSolrDeletionPolicy2, TestSlowCompositeReaderWrapper, TestDocumentBuilder, OutOfBoxZkACLAndCredentialsProvidersTest, RestartWhileUpdatingTest, DisMaxRequestHandlerTest, TestSolrConfigHandlerCloud, TestHighFrequencyDictionaryFactory, TestRawResponseWriter, BJQParserTest, TestLockTree, TestDistributedStatsComponentCardinality, TestRequestForwarding, TestPseudoReturnFields, TestReloadAndDeleteDocs, TestFieldCacheSanityChecker, AlternateDirectoryTest, SimpleMLTQParserTest, TestNonDefinedSimilarityFactory, NumericFieldsTest, ReturnFieldsTest, RequiredFieldsTest, TestHdfsBackupRestoreCore, SolrCoreTest, DistributedVersionInfoTest, SyncSliceTest, TestSolr4Spatial, TestQueryWrapperFilter, TestCSVLoader, ExternalFileFieldSortTest, CloudExitableDirectoryReaderTest, TestInfoStreamLogging, TestIntervalFaceting, TestSolr4Spatial2, TestCloudDeleteByQuery, TestManagedResourceStorage, HLLSerializationTest, DistributedQueryComponentOptimizationTest, TestFoldingMultitermQuery, TestCustomStream, SecurityConfHandlerTest, ClusterStateTest, TestRandomDVFaceting, TestDocSet, HdfsRecoveryZkTest, TestSortingResponseWriter, TestStressUserVersions, TestObjectReleaseTracker, SolrCloudExampleTest, TestIBSimilarityFactory, TestEmbeddedSolrServerConstructors, TestFieldCacheVsDocValues, TestExactSharedStatsCache, TestSolrDynamicMBean, TestFieldResource, DistribDocExpirationUpdateProcessorTest, CdcrVersionReplicationTest, BasicZkTest, TestCrossCoreJoin, DistributedFacetPivotSmallTest, AtomicUpdatesTest, AddBlockUpdateTest, ScriptEngineTest, HdfsCollectionsAPIDistributedZkTest, NotRequiredUniqueKeyTest, BlockJoinFacetSimpleTest, CacheHeaderTest, SynonymTokenizerTest, SpatialHeatmapFacetsTest, TestHdfsUpdateLog, DeleteLastCustomShardedReplicaTest, TestFaceting, TestNumericTerms32, DirectoryFactoryTest, ChangedSchemaMergeTest, SolrRequestParserTest, RegexBoostProcessorTest, ConcurrentDeleteAndCreateCollectionTest, UUIDFieldTest, CursorMarkTest, UniqFieldsUpdateProcessorFactoryTest, RemoteQueryErrorTest, HighlighterConfigTest, TestMinMaxOnMultiValuedField, CreateCollectionCleanupTest, DistributedFacetPivotLargeTest, TestOmitPositions, TestSolrQueryParserResource, RequestLoggingTest, TestPHPSerializedResponseWriter, TestHashQParserPlugin, JSONWriterTest, DistributedDebugComponentTest, OverseerTaskQueueTest, TestFastWriter, MBeansHandlerTest, TestPKIAuthenticationPlugin, TestHdfsCloudBackupRestore, TestQuerySenderNoQuery, OutputWriterTest, BasicDistributedZkTest, BasicDistributedZk2Test, LeaderElectionIntegrationTest, ShardRoutingTest, TestReplicationHandler, ClusterStateUpdateTest, ZkSolrClientTest, TestRecovery, DistributedSpellCheckComponentTest, TermVectorComponentDistributedTest, ZkControllerTest, TestRealTimeGet, TestJoin, TestRangeQuery, StandardRequestHandlerTest, DocumentAnalysisRequestHandlerTest, TermsComponentTest, RequestHandlersTest, TermVectorComponentTest, FastVectorHighlighterTest, SolrPluginUtilsTest, QueryParsingTest, TestComponentsName, TestBinaryResponseWriter, UpdateParamsTest, TestStressRecovery, DirectSolrConnectionTest, TestPhraseSuggestions, TestCodecSupport, TestPerFieldSimilarity, TestJmxMonitoredMap, TestFastOutputStream, DateMathParserTest, PreAnalyzedFieldTest, PrimUtilsTest, DateFieldTest, RAMDirectoryFactoryTest, TestLRUCache, ZkNodePropsTest, SystemInfoHandlerTest, FileUtilsTest, CircularListTest, DistributedMLTComponentTest, TestRTGBase, CursorPagingTest, DistributedIntervalFacetingTest, TestJettySolrRunner, ActionThrottleTest, AssignTest, AsyncCallRequestStatusResponseTest, CdcrReplicationDistributedZkTest, CdcrReplicationHandlerTest, CdcrRequestHandlerTest, CleanupOldIndexTest, DeleteNodeTest, DeleteShardTest, ForceLeaderTest, PeerSyncReplicationTest, TestCloudPseudoReturnFields, TestConfigSetsAPIZkFailure, TestDistribDocBasedVersion, TestLeaderElectionZkExpiry, TestLeaderInitiatedRecoveryThread, TestMiniSolrCloudClusterSSL, TestSSLRandomization, TestSizeLimitedDistributedMap, TestSolrCloudWithKerberosAlt, TestStressCloudBlindAtomicUpdates, TlogReplayBufferedWhileIndexingTest, TriLevelCompositeIdRoutingTest, RuleEngineTest, RulesTest, TestReplicationHandlerBackup, CoreAdminRequestStatusTest, StatsReloadRaceTest, DistributedFacetExistsSmallTest, TestPivotHelperCode, TestTrackingShardHandlerFactory, TestManagedResource, TestCopyFieldCollectionResource, TestDynamicFieldCollectionResource, TestFieldTypeCollectionResource, TestSchemaNameResource, TestSerializedLuceneMatchVersion, TestUniqueKeyFieldResource, TestManagedSynonymFilterFactory, BooleanFieldTest, EnumFieldTest, TestCloudManagedSchema, TestFieldSortValues, TestOverriddenPrefixQueryForCustomFieldType, TestReRankQParserPlugin, TestReloadDeadlock, TestSearcherReuse, TestXmlQParser, TestXmlQParserPlugin, TestJsonFacets, TestExactStatsCache, BasicAuthIntegrationTest, ResponseHeaderTest, ConjunctionSolrSpellCheckerTest, TestAnalyzeInfixSuggestions, TestBlendedInfixSuggestions, BlockCacheTest, TestFieldCache, TestLegacyFieldCache, TestDocBasedVersionConstraints, IgnoreCommitOptimizeUpdateProcessorFactoryTest, PreAnalyzedUpdateProcessorTest, TestNamedUpdateProcessors]
[junit4] Completed [641/641 (1!)] on J0 in 22.51s, 1 test, 1 error <<< FAILURES!
[...truncated 60354 lines...]