Build: https://jenkins.thetaphi.de/job/Lucene-Solr-master-Linux/20335/ Java: 64bit/jdk-9-ea+181 -XX:-UseCompressedOops -XX:+UseG1GC --illegal-access=deny
1 tests failed. FAILED: org.apache.solr.client.solrj.io.stream.StreamExpressionTest.testExecutorStream Error Message: Error from server at http://127.0.0.1:40385/solr/mainCorpus_shard2_replica_n3: Expected mime type application/octet-stream but got text/html. <html> <head> <meta http-equiv="Content-Type" content="text/html;charset=ISO-8859-1"/> <title>Error 404 </title> </head> <body> <h2>HTTP ERROR: 404</h2> <p>Problem accessing /solr/mainCorpus_shard2_replica_n3/update. Reason: <pre> Can not find: /solr/mainCorpus_shard2_replica_n3/update</pre></p> <hr /><a href="http://eclipse.org/jetty";>Powered by Jetty:// 9.3.20.v20170531</a><hr/> </body> </html> Stack Trace: org.apache.solr.client.solrj.impl.CloudSolrClient$RouteException: Error from server at http://127.0.0.1:40385/solr/mainCorpus_shard2_replica_n3: Expected mime type application/octet-stream but got text/html. <html> <head> <meta http-equiv="Content-Type" content="text/html;charset=ISO-8859-1"/> <title>Error 404 </title> </head> <body> <h2>HTTP ERROR: 404</h2> <p>Problem accessing /solr/mainCorpus_shard2_replica_n3/update. Reason: <pre> Can not find: /solr/mainCorpus_shard2_replica_n3/update</pre></p> <hr /><a href="http://eclipse.org/jetty";>Powered by Jetty:// 9.3.20.v20170531</a><hr/> </body> </html> at __randomizedtesting.SeedInfo.seed([9391CF1B04EAEA56:B1514EE02780C046]:0) at org.apache.solr.client.solrj.impl.CloudSolrClient.directUpdate(CloudSolrClient.java:539) at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:993) at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:862) at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:793) at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:178) at org.apache.solr.client.solrj.request.UpdateRequest.commit(UpdateRequest.java:233) at org.apache.solr.client.solrj.io.stream.StreamExpressionTest.testExecutorStream(StreamExpressionTest.java:6816) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:564) at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713) at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907) at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943) at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48) at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817) at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468) at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916) at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802) at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852) at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53) at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) at java.base/java.lang.Thread.run(Thread.java:844) Caused by: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:40385/solr/mainCorpus_shard2_replica_n3: Expected mime type application/octet-stream but got text/html. <html> <head> <meta http-equiv="Content-Type" content="text/html;charset=ISO-8859-1"/> <title>Error 404 </title> </head> <body> <h2>HTTP ERROR: 404</h2> <p>Problem accessing /solr/mainCorpus_shard2_replica_n3/update. Reason: <pre> Can not find: /solr/mainCorpus_shard2_replica_n3/update</pre></p> <hr /><a href="http://eclipse.org/jetty";>Powered by Jetty:// 9.3.20.v20170531</a><hr/> </body> </html> at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:591) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:253) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:242) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:483) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:413) at org.apache.solr.client.solrj.impl.CloudSolrClient.lambda$directUpdate$0(CloudSolrClient.java:516) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) ... 1 more Build Log: [...truncated 14001 lines...] [junit4] Suite: org.apache.solr.client.solrj.io.stream.StreamExpressionTest [junit4] 2> 78385 INFO (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom [junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/init-core-data-001 [junit4] 2> 78386 INFO (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true [junit4] 2> 78387 INFO (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason="", ssl=0.0/0.0, value=0.0/0.0, clientAuth=0.0/0.0) [junit4] 2> 78387 INFO (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 4 servers in /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001 [junit4] 2> 78387 INFO (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 78387 INFO (Thread-128) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0 [junit4] 2> 78387 INFO (Thread-128) [ ] o.a.s.c.ZkTestServer Starting server [junit4] 2> 78419 ERROR (Thread-128) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes [junit4] 2> 78488 INFO (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:32981 [junit4] 2> 78539 INFO (jetty-launcher-777-thread-3) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 [junit4] 2> 78541 INFO (jetty-launcher-777-thread-2) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 [junit4] 2> 78541 INFO (jetty-launcher-777-thread-1) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 [junit4] 2> 78555 INFO (jetty-launcher-777-thread-4) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 [junit4] 2> 78580 INFO (jetty-launcher-777-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@178768f9{/solr,null,AVAILABLE} [junit4] 2> 78582 INFO (jetty-launcher-777-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@61cb9fb8{HTTP/1.1,[http/1.1]}{127.0.0.1:46715} [junit4] 2> 78582 INFO (jetty-launcher-777-thread-1) [ ] o.e.j.s.Server Started @80132ms [junit4] 2> 78582 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=46715} [junit4] 2> 78583 ERROR (jetty-launcher-777-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 78583 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0.0 [junit4] 2> 78583 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 78583 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 78583 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-17T19:43:13.605381Z [junit4] 2> 78586 INFO (jetty-launcher-777-thread-4) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1673b17{/solr,null,AVAILABLE} [junit4] 2> 78588 INFO (jetty-launcher-777-thread-3) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@115b8486{/solr,null,AVAILABLE} [junit4] 2> 78588 INFO (jetty-launcher-777-thread-3) [ ] o.e.j.s.AbstractConnector Started ServerConnector@5e2bc8d0{HTTP/1.1,[http/1.1]}{127.0.0.1:40385} [junit4] 2> 78588 INFO (jetty-launcher-777-thread-3) [ ] o.e.j.s.Server Started @80137ms [junit4] 2> 78588 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=40385} [junit4] 2> 78588 ERROR (jetty-launcher-777-thread-3) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 78588 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0.0 [junit4] 2> 78588 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 78589 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 78589 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-17T19:43:13.611046Z [junit4] 2> 78594 INFO (jetty-launcher-777-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@435bff5f{/solr,null,AVAILABLE} [junit4] 2> 78595 INFO (jetty-launcher-777-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@7d70128e{HTTP/1.1,[http/1.1]}{127.0.0.1:41331} [junit4] 2> 78595 INFO (jetty-launcher-777-thread-4) [ ] o.e.j.s.AbstractConnector Started ServerConnector@14d646b7{HTTP/1.1,[http/1.1]}{127.0.0.1:37067} [junit4] 2> 78595 INFO (jetty-launcher-777-thread-2) [ ] o.e.j.s.Server Started @80145ms [junit4] 2> 78595 INFO (jetty-launcher-777-thread-4) [ ] o.e.j.s.Server Started @80145ms [junit4] 2> 78595 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=41331} [junit4] 2> 78595 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=37067} [junit4] 2> 78596 ERROR (jetty-launcher-777-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 78596 ERROR (jetty-launcher-777-thread-4) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 78596 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0.0 [junit4] 2> 78596 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0.0 [junit4] 2> 78596 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 78596 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 78596 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 78597 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 78597 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-17T19:43:13.619254Z [junit4] 2> 78597 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-08-17T19:43:13.618430Z [junit4] 2> 78603 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 78611 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 78614 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 78615 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 78642 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:32981/solr [junit4] 2> 78667 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:32981/solr [junit4] 2> 78668 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:32981/solr [junit4] 2> 78673 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:32981/solr [junit4] 2> 78678 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception [junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x15df1b89a030006, likely client has closed socket [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239) [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> 78694 WARN (jetty-launcher-777-thread-4) [ ] o.a.s.c.ZkController The _default configset could not be uploaded. Please provide 'solr.default.confdir' parameter that points to a configset intended to be the default. Current 'solr.default.confdir' value: null [junit4] 2> 78695 WARN (jetty-launcher-777-thread-2) [ ] o.a.s.c.ZkController The _default configset could not be uploaded. Please provide 'solr.default.confdir' parameter that points to a configset intended to be the default. Current 'solr.default.confdir' value: null [junit4] 2> 78694 WARN (jetty-launcher-777-thread-1) [ ] o.a.s.c.ZkController The _default configset could not be uploaded. Please provide 'solr.default.confdir' parameter that points to a configset intended to be the default. Current 'solr.default.confdir' value: null [junit4] 2> 78694 WARN (jetty-launcher-777-thread-3) [ ] o.a.s.c.ZkController The _default configset could not be uploaded. Please provide 'solr.default.confdir' parameter that points to a configset intended to be the default. Current 'solr.default.confdir' value: null [junit4] 2> 78699 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 78699 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 78699 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 78699 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 78699 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:37067_solr [junit4] 2> 78700 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40385_solr [junit4] 2> 78700 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46715_solr [junit4] 2> 78700 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41331_solr [junit4] 2> 78700 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.c.Overseer Overseer (id=98500542032183308-127.0.0.1:37067_solr-n_0000000000) starting [junit4] 2> 78701 INFO (zkCallback-797-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3) [junit4] 2> 78714 INFO (zkCallback-798-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3) [junit4] 2> 78714 INFO (zkCallback-795-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3) [junit4] 2> 78720 INFO (zkCallback-799-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3) [junit4] 2> 78800 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37067_solr [junit4] 2> 78801 INFO (zkCallback-799-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 78810 INFO (zkCallback-797-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 78810 INFO (zkCallback-798-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 78810 INFO (zkCallback-795-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4) [junit4] 2> 78817 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_46715.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78855 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40385.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78859 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_46715.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78859 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_46715.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78862 INFO (jetty-launcher-777-thread-1) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node1/. [junit4] 2> 78863 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_41331.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78868 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40385.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78868 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40385.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78872 INFO (jetty-launcher-777-thread-3) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node2/. [junit4] 2> 78873 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_41331.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78874 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_41331.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78875 INFO (jetty-launcher-777-thread-2) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node3/. [junit4] 2> 78880 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37067.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78893 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37067.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78898 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37067.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 78899 INFO (jetty-launcher-777-thread-4) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node4/. [junit4] 2> 78988 INFO (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 78988 INFO (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:32981/solr ready [junit4] 2> 78994 INFO (qtp1314863458-1633) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf&name=collection1&nrtReplicas=1&action=CREATE&numShards=2&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 79006 INFO (OverseerThreadFactory-190-thread-1) [ ] o.a.s.c.CreateCollectionCmd Create collection collection1 [junit4] 2> 79110 INFO (OverseerStateUpdate-98500542032183308-127.0.0.1:37067_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"collection1", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"collection1_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:41331/solr";, [junit4] 2> "type":"NRT"} [junit4] 2> 79112 INFO (OverseerStateUpdate-98500542032183308-127.0.0.1:37067_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"collection1", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"collection1_shard2_replica_n2", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:40385/solr";, [junit4] 2> "type":"NRT"} [junit4] 2> 79316 INFO (qtp403395034-1628) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node4&collection.configName=conf&newCollection=true&name=collection1_shard2_replica_n2&action=CREATE&numShards=2&collection=collection1&shard=shard2&wt=javabin&version=2&replicaType=NRT [junit4] 2> 79316 INFO (qtp403395034-1628) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 79320 INFO (qtp919056506-1627) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&newCollection=true&name=collection1_shard1_replica_n1&action=CREATE&numShards=2&collection=collection1&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 79320 INFO (qtp919056506-1627) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 79433 INFO (zkCallback-798-thread-1) [ ] 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> 79434 INFO (zkCallback-797-thread-1) [ ] 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> 79435 INFO (zkCallback-798-thread-2) [ ] 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> 79438 INFO (zkCallback-797-thread-2) [ ] 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> 80337 INFO (qtp919056506-1627) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0 [junit4] 2> 80339 INFO (qtp403395034-1628) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0 [junit4] 2> 80365 INFO (qtp919056506-1627) [ ] o.a.s.s.IndexSchema [collection1_shard1_replica_n1] Schema name=test [junit4] 2> 80370 INFO (qtp403395034-1628) [ ] o.a.s.s.IndexSchema [collection1_shard2_replica_n2] Schema name=test [junit4] 2> 80701 WARN (qtp919056506-1627) [ ] o.a.s.s.IndexSchema Field lowerfilt1and2 is not multivalued and destination for multiple copyFields (2) [junit4] 2> 80701 WARN (qtp919056506-1627) [ ] o.a.s.s.IndexSchema Field text is not multivalued and destination for multiple copyFields (3) [junit4] 2> 80701 INFO (qtp919056506-1627) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 80701 INFO (qtp919056506-1627) [ ] o.a.s.c.CoreContainer Creating SolrCore 'collection1_shard1_replica_n1' using configuration from collection collection1, trusted=true [junit4] 2> 80702 INFO (qtp919056506-1627) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_41331.solr.core.collection1.shard1.replica_n1' (registry 'solr.core.collection1.shard1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 80702 INFO (qtp919056506-1627) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 80702 INFO (qtp919056506-1627) [ ] o.a.s.c.SolrCore [[collection1_shard1_replica_n1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node3/collection1_shard1_replica_n1], dataDir=[/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node3/./collection1_shard1_replica_n1/data/] [junit4] 2> 80714 WARN (qtp403395034-1628) [ ] o.a.s.s.IndexSchema Field lowerfilt1and2 is not multivalued and destination for multiple copyFields (2) [junit4] 2> 80714 WARN (qtp403395034-1628) [ ] o.a.s.s.IndexSchema Field text is not multivalued and destination for multiple copyFields (3) [junit4] 2> 80715 INFO (qtp403395034-1628) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 80715 INFO (qtp403395034-1628) [ ] o.a.s.c.CoreContainer Creating SolrCore 'collection1_shard2_replica_n2' using configuration from collection collection1, trusted=true [junit4] 2> 80720 INFO (qtp403395034-1628) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40385.solr.core.collection1.shard2.replica_n2' (registry 'solr.core.collection1.shard2.replica_n2') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 80721 INFO (qtp403395034-1628) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 80721 INFO (qtp403395034-1628) [ ] o.a.s.c.SolrCore [[collection1_shard2_replica_n2] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node2/collection1_shard2_replica_n2], dataDir=[/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node2/./collection1_shard2_replica_n2/data/] [junit4] 2> 80882 INFO (qtp403395034-1628) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 80882 INFO (qtp403395034-1628) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 80884 INFO (qtp403395034-1628) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 80884 INFO (qtp403395034-1628) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 80895 INFO (qtp919056506-1627) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 80895 INFO (qtp919056506-1627) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 80897 INFO (qtp919056506-1627) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 80897 INFO (qtp919056506-1627) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 80899 INFO (qtp919056506-1627) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@11114825[collection1_shard1_replica_n1] main] [junit4] 2> 80900 INFO (qtp919056506-1627) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 80919 INFO (qtp919056506-1627) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 80919 INFO (qtp919056506-1627) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 80921 INFO (searcherExecutor-196-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard1_replica_n1] Registered new searcher Searcher@11114825[collection1_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 80921 INFO (qtp919056506-1627) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1576008675169927168 [junit4] 2> 80922 INFO (qtp403395034-1628) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@37ee5356[collection1_shard2_replica_n2] main] [junit4] 2> 80928 INFO (qtp919056506-1627) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 80928 INFO (qtp919056506-1627) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 80928 INFO (qtp919056506-1627) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:41331/solr/collection1_shard1_replica_n1/ [junit4] 2> 80929 INFO (qtp919056506-1627) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 80929 INFO (qtp919056506-1627) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:41331/solr/collection1_shard1_replica_n1/ has no replicas [junit4] 2> 80929 INFO (qtp919056506-1627) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 80931 INFO (qtp919056506-1627) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:41331/solr/collection1_shard1_replica_n1/ shard1 [junit4] 2> 80932 INFO (qtp403395034-1628) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 80933 INFO (qtp403395034-1628) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 80933 INFO (qtp403395034-1628) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 80934 INFO (searcherExecutor-197-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard2_replica_n2] Registered new searcher Searcher@37ee5356[collection1_shard2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 80934 INFO (qtp403395034-1628) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1576008675183558656 [junit4] 2> 80940 INFO (qtp403395034-1628) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 80940 INFO (qtp403395034-1628) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 80940 INFO (qtp403395034-1628) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:40385/solr/collection1_shard2_replica_n2/ [junit4] 2> 80940 INFO (qtp403395034-1628) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 80940 INFO (qtp403395034-1628) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:40385/solr/collection1_shard2_replica_n2/ has no replicas [junit4] 2> 80940 INFO (qtp403395034-1628) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 80942 INFO (qtp403395034-1628) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:40385/solr/collection1_shard2_replica_n2/ shard2 [junit4] 2> 81043 INFO (zkCallback-797-thread-2) [ ] 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> 81043 INFO (zkCallback-798-thread-1) [ ] 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> 81043 INFO (zkCallback-797-thread-1) [ ] 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> 81043 INFO (zkCallback-798-thread-2) [ ] 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> 81082 INFO (qtp919056506-1627) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 81083 INFO (qtp919056506-1627) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&newCollection=true&name=collection1_shard1_replica_n1&action=CREATE&numShards=2&collection=collection1&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1763 [junit4] 2> 81093 INFO (qtp403395034-1628) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 81100 INFO (qtp403395034-1628) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node4&collection.configName=conf&newCollection=true&name=collection1_shard2_replica_n2&action=CREATE&numShards=2&collection=collection1&shard=shard2&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1784 [junit4] 2> 81104 INFO (qtp1314863458-1633) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 81205 INFO (zkCallback-797-thread-2) [ ] 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> 81205 INFO (zkCallback-797-thread-1) [ ] 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> 81205 INFO (zkCallback-798-thread-2) [ ] 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> 81205 INFO (zkCallback-798-thread-1) [ ] 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> 82105 INFO (qtp1314863458-1633) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf&name=collection1&nrtReplicas=1&action=CREATE&numShards=2&wt=javabin&version=2} status=0 QTime=3111 [junit4] 2> 82106 INFO (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.s.c.AbstractDistribZkTestBase Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):90 [junit4] 2> 82107 INFO (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.s.c.AbstractDistribZkTestBase Recoveries finished - collection: collection1 [junit4] 2> 82122 INFO (TEST-StreamExpressionTest.testLength-seed#[9391CF1B04EAEA56]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testLength [junit4] 2> 82166 INFO (qtp403395034-1650) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/update params={update.distrib=TOLEADER&distrib.from=http://127.0.0.1:41331/solr/collection1_shard1_replica_n1/&wt=javabin&version=2}{deleteByQuery=*:* (-1576008676447092736)} 0 27 [junit4] 2> 82168 INFO (qtp919056506-1624) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008676477501440,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 82168 INFO (qtp919056506-1624) [ ] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit. [junit4] 2> 82186 INFO (qtp919056506-1624) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 82186 INFO (qtp919056506-1624) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard1_replica_n1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:41331/solr/collection1_shard1_replica_n1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 18 [junit4] 2> 82186 INFO (qtp403395034-1652) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008676496375808,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 82186 INFO (qtp403395034-1652) [ ] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit. [junit4] 2> 82187 INFO (qtp403395034-1652) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 82187 INFO (qtp403395034-1652) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:41331/solr/collection1_shard1_replica_n1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 1 [junit4] 2> 82188 INFO (qtp919056506-1623) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard1_replica_n1] webapp=/solr path=/update params={_stateVer_=collection1:4&commit=true&wt=javabin&version=2}{deleteByQuery=*:* (-1576008676438704128),commit=} 0 64 [junit4] 2> 82228 INFO (qtp919056506-1647) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard1_replica_n1] webapp=/solr path=/update params={_stateVer_=collection1:4&wt=javabin&version=2}{add=[1 (1576008676532027392), 4 (1576008676539367424), 8 (1576008676539367425), 10 (1576008676539367426), 11 (1576008676539367427), 12 (1576008676540416000), 13 (1576008676540416001), 14 (1576008676540416002)]} 0 8 [junit4] 2> 82239 INFO (qtp403395034-1631) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/update params={_stateVer_=collection1:4&wt=javabin&version=2}{add=[2 (1576008676533075968), 3 (1576008676550901760), 5 (1576008676551950336), 6 (1576008676551950337), 7 (1576008676551950338), 9 (1576008676551950339)]} 0 18 [junit4] 2> 82241 INFO (qtp919056506-1621) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008676554047488,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 82243 INFO (qtp403395034-1628) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008676556144640,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 82245 INFO (qtp919056506-1621) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@89dcfa6 commitCommandVersion:1576008676554047488 [junit4] 2> 82249 INFO (qtp403395034-1628) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@a2bff96 commitCommandVersion:1576008676556144640 [junit4] 2> 82277 INFO (qtp403395034-1628) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@66635dc1[collection1_shard2_replica_n2] main] [junit4] 2> 82278 INFO (qtp403395034-1628) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 82281 INFO (searcherExecutor-197-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard2_replica_n2] Registered new searcher Searcher@66635dc1[collection1_shard2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(8.0.0):c6)))} [junit4] 2> 82281 INFO (qtp403395034-1628) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:41331/solr/collection1_shard1_replica_n1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 38 [junit4] 2> 82284 INFO (qtp919056506-1621) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@4d92c35a[collection1_shard1_replica_n1] main] [junit4] 2> 82284 INFO (qtp919056506-1621) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 82285 INFO (searcherExecutor-196-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard1_replica_n1] Registered new searcher Searcher@4d92c35a[collection1_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(8.0.0):c8)))} [junit4] 2> 82285 INFO (qtp919056506-1621) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard1_replica_n1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:41331/solr/collection1_shard1_replica_n1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 43 [junit4] 2> 82285 INFO (qtp919056506-1627) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard1_replica_n1] webapp=/solr path=/update params={_stateVer_=collection1:4&commit=true&wt=javabin&version=2}{commit=} 0 45 [junit4] 2> 82292 INFO (qtp919056506-1647) [ ] o.a.s.c.S.Request [collection1_shard1_replica_n1] webapp=/solr path=/stream params={indent=off&expr=let(a%3Dsearch(collection1,+q%3D"col_s:a",+fl%3D"price_f,+order_i",+sort%3D"order_i+asc"),+b%3Dsearch(collection1,+q%3D"col_s:b",+fl%3D"price_f,+order_i",+sort%3D"order_i+asc"),+c%3Dcol(a,+price_f),+d%3Dcol(b,+price_f),+e%3Dregress(c,+d),+tuple(regress%3De,+p%3Dpredict(e,+300),+l%3Dlength(d)))&wt=json&version=2.2} status=0 QTime=4 [junit4] 2> 82299 INFO (qtp919056506-1647) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 82299 INFO (qtp919056506-1647) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:32981/solr ready [junit4] 2> 82312 INFO (qtp403395034-1646) [ ] o.a.s.c.S.Request [collection1_shard2_replica_n2] webapp=/solr path=/select params={q=col_s:a&distrib=false&fl=price_f,+order_i&sort=order_i+asc&wt=json&version=2.2} hits=5 status=0 QTime=0 [junit4] 2> 82316 INFO (qtp919056506-1624) [ ] o.a.s.c.S.Request [collection1_shard1_replica_n1] webapp=/solr path=/select params={q=col_s:a&distrib=false&fl=price_f,+order_i&sort=order_i+asc&wt=json&version=2.2} hits=2 status=0 QTime=0 [junit4] 2> 82338 INFO (qtp403395034-1628) [ ] o.a.s.c.S.Request [collection1_shard2_replica_n2] webapp=/solr path=/select params={q=col_s:b&distrib=false&fl=price_f,+order_i&sort=order_i+asc&wt=json&version=2.2} hits=1 status=0 QTime=14 [junit4] 2> 82340 INFO (qtp919056506-1621) [ ] o.a.s.c.S.Request [collection1_shard1_replica_n1] webapp=/solr path=/select params={q=col_s:b&distrib=false&fl=price_f,+order_i&sort=order_i+asc&wt=json&version=2.2} hits=6 status=0 QTime=0 [junit4] 2> 82376 INFO (TEST-StreamExpressionTest.testLength-seed#[9391CF1B04EAEA56]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testLength [junit4] 2> 82395 INFO (TEST-StreamExpressionTest.testParallelCommitStream-seed#[9391CF1B04EAEA56]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testParallelCommitStream [junit4] 2> 82405 INFO (qtp403395034-1631) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@7b9fe4c9[collection1_shard2_replica_n2] realtime] [junit4] 2> 82405 INFO (qtp919056506-1624) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@140b6048[collection1_shard1_replica_n1] realtime] [junit4] 2> 82406 INFO (qtp403395034-1631) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/update params={update.distrib=TOLEADER&distrib.from=http://127.0.0.1:41331/solr/collection1_shard1_replica_n1/&wt=javabin&version=2}{deleteByQuery=*:* (-1576008676718673920)} 0 8 [junit4] 2> 82407 INFO (qtp919056506-1623) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008676728111104,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 82407 INFO (qtp919056506-1623) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@89dcfa6 commitCommandVersion:1576008676728111104 [junit4] 2> 82408 INFO (qtp403395034-1628) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008676729159680,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 82408 INFO (qtp403395034-1628) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@a2bff96 commitCommandVersion:1576008676729159680 [junit4] 2> 82408 INFO (qtp403395034-1628) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@76d3d83e[collection1_shard2_replica_n2] main] [junit4] 2> 82408 INFO (qtp403395034-1628) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 82409 INFO (qtp919056506-1623) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@3739880b[collection1_shard1_replica_n1] main] [junit4] 2> 82409 INFO (searcherExecutor-197-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard2_replica_n2] Registered new searcher Searcher@76d3d83e[collection1_shard2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 82409 INFO (qtp919056506-1623) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 82410 INFO (qtp403395034-1628) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:41331/solr/collection1_shard1_replica_n1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 2 [junit4] 2> 82411 INFO (searcherExecutor-196-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard1_replica_n1] Registered new searcher Searcher@3739880b[collection1_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 82418 INFO (qtp919056506-1623) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard1_replica_n1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:41331/solr/collection1_shard1_replica_n1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 10 [junit4] 2> 82418 INFO (qtp919056506-1624) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard1_replica_n1] webapp=/solr path=/update params={_stateVer_=collection1:4&commit=true&wt=javabin&version=2}{deleteByQuery=*:* (-1576008676717625344),commit=} 0 22 [junit4] 2> 82419 INFO (qtp1314863458-1634) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf&name=parallelDestinationCollection&nrtReplicas=1&action=CREATE&numShards=2&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 82433 INFO (OverseerThreadFactory-190-thread-2) [ ] o.a.s.c.CreateCollectionCmd Create collection parallelDestinationCollection [junit4] 2> 82433 INFO (OverseerCollectionConfigSetProcessor-98500542032183308-127.0.0.1:37067_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 82644 INFO (OverseerStateUpdate-98500542032183308-127.0.0.1:37067_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"parallelDestinationCollection", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"parallelDestinationCollection_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:40385/solr";, [junit4] 2> "type":"NRT"} [junit4] 2> 82646 INFO (OverseerStateUpdate-98500542032183308-127.0.0.1:37067_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"parallelDestinationCollection", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"parallelDestinationCollection_shard2_replica_n2", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:37067/solr";, [junit4] 2> "type":"NRT"} [junit4] 2> 82847 INFO (qtp403395034-1651) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&newCollection=true&name=parallelDestinationCollection_shard1_replica_n1&action=CREATE&numShards=2&collection=parallelDestinationCollection&shard=shard1&wt=javabin&version=2&replicaType=NRT [junit4] 2> 82852 INFO (qtp506020297-1642) [ ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node4&collection.configName=conf&newCollection=true&name=parallelDestinationCollection_shard2_replica_n2&action=CREATE&numShards=2&collection=parallelDestinationCollection&shard=shard2&wt=javabin&version=2&replicaType=NRT [junit4] 2> 82852 INFO (qtp506020297-1642) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 82974 INFO (zkCallback-797-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 82975 INFO (zkCallback-797-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 82974 INFO (zkCallback-799-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 82975 INFO (zkCallback-799-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 83858 INFO (qtp403395034-1651) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0 [junit4] 2> 83865 INFO (qtp403395034-1651) [ ] o.a.s.s.IndexSchema [parallelDestinationCollection_shard1_replica_n1] Schema name=test [junit4] 2> 83948 INFO (qtp506020297-1642) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0 [junit4] 2> 83957 INFO (qtp506020297-1642) [ ] o.a.s.s.IndexSchema [parallelDestinationCollection_shard2_replica_n2] Schema name=test [junit4] 2> 83970 WARN (qtp403395034-1651) [ ] o.a.s.s.IndexSchema Field lowerfilt1and2 is not multivalued and destination for multiple copyFields (2) [junit4] 2> 83971 WARN (qtp403395034-1651) [ ] o.a.s.s.IndexSchema Field text is not multivalued and destination for multiple copyFields (3) [junit4] 2> 83971 INFO (qtp403395034-1651) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 83971 INFO (qtp403395034-1651) [ ] o.a.s.c.CoreContainer Creating SolrCore 'parallelDestinationCollection_shard1_replica_n1' using configuration from collection parallelDestinationCollection, trusted=true [junit4] 2> 83971 INFO (qtp403395034-1651) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40385.solr.core.parallelDestinationCollection.shard1.replica_n1' (registry 'solr.core.parallelDestinationCollection.shard1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 83971 INFO (qtp403395034-1651) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 83971 INFO (qtp403395034-1651) [ ] o.a.s.c.SolrCore [[parallelDestinationCollection_shard1_replica_n1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node2/parallelDestinationCollection_shard1_replica_n1], dataDir=[/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node2/./parallelDestinationCollection_shard1_replica_n1/data/] [junit4] 2> 84053 INFO (qtp403395034-1651) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 84053 INFO (qtp403395034-1651) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 84055 INFO (qtp403395034-1651) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 84055 INFO (qtp403395034-1651) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 84056 INFO (qtp403395034-1651) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@451b5f52[parallelDestinationCollection_shard1_replica_n1] main] [junit4] 2> 84057 WARN (qtp506020297-1642) [ ] o.a.s.s.IndexSchema Field lowerfilt1and2 is not multivalued and destination for multiple copyFields (2) [junit4] 2> 84057 WARN (qtp506020297-1642) [ ] o.a.s.s.IndexSchema Field text is not multivalued and destination for multiple copyFields (3) [junit4] 2> 84057 INFO (qtp506020297-1642) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id [junit4] 2> 84057 INFO (qtp506020297-1642) [ ] o.a.s.c.CoreContainer Creating SolrCore 'parallelDestinationCollection_shard2_replica_n2' using configuration from collection parallelDestinationCollection, trusted=true [junit4] 2> 84057 INFO (qtp403395034-1651) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 84057 INFO (qtp403395034-1651) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 84057 INFO (qtp506020297-1642) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37067.solr.core.parallelDestinationCollection.shard2.replica_n2' (registry 'solr.core.parallelDestinationCollection.shard2.replica_n2') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@65c56746 [junit4] 2> 84058 INFO (qtp506020297-1642) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 84058 INFO (qtp506020297-1642) [ ] o.a.s.c.SolrCore [[parallelDestinationCollection_shard2_replica_n2] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node4/parallelDestinationCollection_shard2_replica_n2], dataDir=[/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001/tempDir-001/node4/./parallelDestinationCollection_shard2_replica_n2/data/] [junit4] 2> 84058 INFO (qtp403395034-1651) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 84059 INFO (qtp403395034-1651) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1576008678460358656 [junit4] 2> 84062 INFO (searcherExecutor-206-thread-1) [ ] o.a.s.c.SolrCore [parallelDestinationCollection_shard1_replica_n1] Registered new searcher Searcher@451b5f52[parallelDestinationCollection_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 84074 INFO (qtp403395034-1651) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 84074 INFO (qtp403395034-1651) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 84074 INFO (qtp403395034-1651) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:40385/solr/parallelDestinationCollection_shard1_replica_n1/ [junit4] 2> 84074 INFO (qtp403395034-1651) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 84074 INFO (qtp403395034-1651) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:40385/solr/parallelDestinationCollection_shard1_replica_n1/ has no replicas [junit4] 2> 84074 INFO (qtp403395034-1651) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 84077 INFO (qtp403395034-1651) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:40385/solr/parallelDestinationCollection_shard1_replica_n1/ shard1 [junit4] 2> 84118 INFO (qtp506020297-1642) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 84118 INFO (qtp506020297-1642) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 84120 INFO (qtp506020297-1642) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 84120 INFO (qtp506020297-1642) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 84126 INFO (qtp506020297-1642) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@4512db85[parallelDestinationCollection_shard2_replica_n2] main] [junit4] 2> 84127 INFO (qtp506020297-1642) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 84127 INFO (qtp506020297-1642) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 84128 INFO (qtp506020297-1642) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 [junit4] 2> 84129 INFO (searcherExecutor-211-thread-1) [ ] o.a.s.c.SolrCore [parallelDestinationCollection_shard2_replica_n2] Registered new searcher Searcher@4512db85[parallelDestinationCollection_shard2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 84129 INFO (qtp506020297-1642) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1576008678533758976 [junit4] 2> 84133 INFO (qtp506020297-1642) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 84133 INFO (qtp506020297-1642) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 84134 INFO (qtp506020297-1642) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:37067/solr/parallelDestinationCollection_shard2_replica_n2/ [junit4] 2> 84134 INFO (qtp506020297-1642) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me [junit4] 2> 84134 INFO (qtp506020297-1642) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:37067/solr/parallelDestinationCollection_shard2_replica_n2/ has no replicas [junit4] 2> 84134 INFO (qtp506020297-1642) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 84136 INFO (qtp506020297-1642) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:37067/solr/parallelDestinationCollection_shard2_replica_n2/ shard2 [junit4] 2> 84238 INFO (zkCallback-799-thread-3) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 84238 INFO (zkCallback-797-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 84238 INFO (zkCallback-797-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 84238 INFO (zkCallback-799-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 84277 INFO (qtp403395034-1651) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 84278 INFO (qtp403395034-1651) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&newCollection=true&name=parallelDestinationCollection_shard1_replica_n1&action=CREATE&numShards=2&collection=parallelDestinationCollection&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1431 [junit4] 2> 84287 INFO (qtp506020297-1642) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 84288 INFO (qtp506020297-1642) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node4&collection.configName=conf&newCollection=true&name=parallelDestinationCollection_shard2_replica_n2&action=CREATE&numShards=2&collection=parallelDestinationCollection&shard=shard2&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1436 [junit4] 2> 84290 INFO (qtp1314863458-1634) [ ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 84389 INFO (zkCallback-797-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 84389 INFO (zkCallback-799-thread-3) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 84389 INFO (zkCallback-799-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 84389 INFO (zkCallback-797-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/parallelDestinationCollection/state.json] for collection [parallelDestinationCollection] has occurred - updating... (live nodes size: [4]) [junit4] 2> 84434 INFO (OverseerCollectionConfigSetProcessor-98500542032183308-127.0.0.1:37067_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000002 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 85294 INFO (qtp1314863458-1634) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf&name=parallelDestinationCollection&nrtReplicas=1&action=CREATE&numShards=2&wt=javabin&version=2} status=0 QTime=2875 [junit4] 2> 85295 INFO (TEST-StreamExpressionTest.testParallelCommitStream-seed#[9391CF1B04EAEA56]) [ ] o.a.s.c.AbstractDistribZkTestBase Wait for recoveries to finish - collection: parallelDestinationCollection failOnTimeout:true timeout (sec):90 [junit4] 2> 85295 INFO (TEST-StreamExpressionTest.testParallelCommitStream-seed#[9391CF1B04EAEA56]) [ ] o.a.s.c.AbstractDistribZkTestBase Recoveries finished - collection: parallelDestinationCollection [junit4] 2> 85307 INFO (qtp403395034-1630) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/update params={_stateVer_=collection1:4&wt=javabin&version=2}{add=[2 (1576008679763738624), 3 (1576008679767932928)]} 0 7 [junit4] 2> 85307 INFO (qtp919056506-1621) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard1_replica_n1] webapp=/solr path=/update params={_stateVer_=collection1:4&wt=javabin&version=2}{add=[0 (1576008679758495744), 4 (1576008679767932928), 1 (1576008679768981504)]} 0 10 [junit4] 2> 85310 INFO (qtp919056506-1625) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008679772127232,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 85310 INFO (qtp919056506-1625) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@89dcfa6 commitCommandVersion:1576008679772127232 [junit4] 2> 85325 INFO (qtp919056506-1625) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@24e43ed1[collection1_shard1_replica_n1] main] [junit4] 2> 85327 INFO (searcherExecutor-196-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard1_replica_n1] Registered new searcher Searcher@24e43ed1[collection1_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_1(8.0.0):c3)))} [junit4] 2> 85327 INFO (qtp919056506-1625) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 85327 INFO (qtp919056506-1625) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard1_replica_n1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:40385/solr/collection1_shard2_replica_n2/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 18 [junit4] 2> 85328 INFO (qtp403395034-1652) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008679791001600,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 85328 INFO (qtp403395034-1652) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@a2bff96 commitCommandVersion:1576008679791001600 [junit4] 2> 85342 INFO (qtp403395034-1652) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@12fac736[collection1_shard2_replica_n2] main] [junit4] 2> 85344 INFO (searcherExecutor-197-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard2_replica_n2] Registered new searcher Searcher@12fac736[collection1_shard2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_1(8.0.0):c2)))} [junit4] 2> 85344 INFO (qtp403395034-1652) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 85344 INFO (qtp403395034-1652) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:40385/solr/collection1_shard2_replica_n2/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 16 [junit4] 2> 85345 INFO (qtp403395034-1631) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/update params={_stateVer_=collection1:4&commit=true&wt=javabin&version=2}{commit=} 0 37 [junit4] 2> 85371 INFO (TEST-StreamExpressionTest.testParallelCommitStream-seed#[9391CF1B04EAEA56]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 85372 INFO (TEST-StreamExpressionTest.testParallelCommitStream-seed#[9391CF1B04EAEA56]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:32981/solr ready [junit4] 2> 85400 INFO (qtp403395034-1628) [ ] o.a.s.c.S.Request [collection1_shard2_replica_n2] webapp=/solr path=/stream params={distrib=false&workerID=0&indent=off&numWorkers=2&expr=commit(parallelDestinationCollection,zkHost%3D"127.0.0.1:32981/solr",batchSize%3D0,waitFlush%3Dfalse,waitSearcher%3Dfalse,softCommit%3Dfalse,update(parallelDestinationCollection,zkHost%3D"127.0.0.1:32981/solr",batchSize%3D2,search(collection1,q%3D"*:*",fl%3D"id,a_s,a_i,a_f,s_multi,i_multi",sort%3D"a_f+asc,+a_i+asc",partitionKeys%3Da_f,zkHost%3D"127.0.0.1:32981/solr")))&wt=json&version=2.2} status=0 QTime=0 [junit4] 2> 85400 INFO (qtp919056506-1627) [ ] o.a.s.c.S.Request [collection1_shard1_replica_n1] webapp=/solr path=/stream params={distrib=false&workerID=1&indent=off&numWorkers=2&expr=commit(parallelDestinationCollection,zkHost%3D"127.0.0.1:32981/solr",batchSize%3D0,waitFlush%3Dfalse,waitSearcher%3Dfalse,softCommit%3Dfalse,update(parallelDestinationCollection,zkHost%3D"127.0.0.1:32981/solr",batchSize%3D2,search(collection1,q%3D"*:*",fl%3D"id,a_s,a_i,a_f,s_multi,i_multi",sort%3D"a_f+asc,+a_i+asc",partitionKeys%3Da_f,zkHost%3D"127.0.0.1:32981/solr")))&wt=json&version=2.2} status=0 QTime=0 [junit4] 2> 85412 INFO (qtp403395034-1646) [ ] o.a.s.c.S.Request [collection1_shard2_replica_n2] webapp=/solr path=/select params={q=*:*&distrib=false&fl=id,a_s,a_i,a_f,s_multi,i_multi&sort=a_f+asc,+a_i+asc&partitionKeys=a_f&fq={!hash+workers%3D2+worker%3D1}&wt=json&version=2.2} hits=0 status=0 QTime=0 [junit4] 2> 85424 INFO (qtp403395034-1650) [ ] o.a.s.c.S.Request [collection1_shard2_replica_n2] webapp=/solr path=/select params={q=*:*&distrib=false&fl=id,a_s,a_i,a_f,s_multi,i_multi&sort=a_f+asc,+a_i+asc&partitionKeys=a_f&fq={!hash+workers%3D2+worker%3D0}&wt=json&version=2.2} hits=2 status=0 QTime=1 [junit4] 2> 85425 INFO (qtp919056506-1624) [ ] o.a.s.c.S.Request [collection1_shard1_replica_n1] webapp=/solr path=/select params={q=*:*&distrib=false&fl=id,a_s,a_i,a_f,s_multi,i_multi&sort=a_f+asc,+a_i+asc&partitionKeys=a_f&fq={!hash+workers%3D2+worker%3D0}&wt=json&version=2.2} hits=3 status=0 QTime=1 [junit4] 2> 85426 INFO (qtp919056506-1629) [ ] o.a.s.c.S.Request [collection1_shard1_replica_n1] webapp=/solr path=/select params={q=*:*&distrib=false&fl=id,a_s,a_i,a_f,s_multi,i_multi&sort=a_f+asc,+a_i+asc&partitionKeys=a_f&fq={!hash+workers%3D2+worker%3D1}&wt=json&version=2.2} hits=0 status=0 QTime=2 [junit4] 2> 85442 INFO (qtp403395034-1630) [ ] o.a.s.u.p.LogUpdateProcessorFactory [parallelDestinationCollection_shard1_replica_n1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[0 (1576008679905296384)]} 0 5 [junit4] 2> 85443 INFO (qtp506020297-1638) [ ] o.a.s.u.p.LogUpdateProcessorFactory [parallelDestinationCollection_shard2_replica_n2] webapp=/solr path=/update params={wt=javabin&version=2}{add=[2 (1576008679904247808)]} 0 7 [junit4] 2> 85445 INFO (qtp506020297-1644) [ ] o.a.s.u.p.LogUpdateProcessorFactory [parallelDestinationCollection_shard2_replica_n2] webapp=/solr path=/update params={wt=javabin&version=2}{add=[3 (1576008679912636416)]} 0 1 [junit4] 2> 85446 INFO (qtp403395034-1650) [ ] o.a.s.u.p.LogUpdateProcessorFactory [parallelDestinationCollection_shard1_replica_n1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[1 (1576008679912636416)]} 0 2 [junit4] 2> 85448 INFO (qtp403395034-1652) [ ] o.a.s.u.p.LogUpdateProcessorFactory [parallelDestinationCollection_shard1_replica_n1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[4 (1576008679916830720)]} 0 0 [junit4] 2> 85453 INFO (qtp403395034-1628) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4) [junit4] 2> 85454 INFO (qtp403395034-1628) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:32981/solr ready [junit4] 2> 85456 INFO (qtp506020297-1639) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008679925219328,optimize=false,openSearcher=true,waitSearcher=false,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 85456 INFO (qtp506020297-1639) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1b7e31ea commitCommandVersion:1576008679925219328 [junit4] 2> 85457 INFO (qtp403395034-1652) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008679926267904,optimize=false,openSearcher=true,waitSearcher=false,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 85457 INFO (qtp403395034-1652) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@34283cf4 commitCommandVersion:1576008679926267904 [junit4] 2> 85486 INFO (qtp506020297-1639) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@4e0cea94[parallelDestinationCollection_shard2_replica_n2] main] [junit4] 2> 85487 INFO (qtp403395034-1652) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@6fc0eb8[parallelDestinationCollection_shard1_replica_n1] main] [junit4] 2> 85488 INFO (searcherExecutor-211-thread-1) [ ] o.a.s.c.SolrCore [parallelDestinationCollection_shard2_replica_n2] Registered new searcher Searcher@4e0cea94[parallelDestinationCollection_shard2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(8.0.0):c2)))} [junit4] 2> 85488 INFO (qtp506020297-1639) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 85488 INFO (qtp506020297-1639) [ ] o.a.s.u.p.LogUpdateProcessorFactory [parallelDestinationCollection_shard2_replica_n2] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=false&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:40385/solr/parallelDestinationCollection_shard1_replica_n1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 31 [junit4] 2> 85489 INFO (qtp403395034-1652) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 85489 INFO (qtp403395034-1652) [ ] o.a.s.u.p.LogUpdateProcessorFactory [parallelDestinationCollection_shard1_replica_n1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=false&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:40385/solr/parallelDestinationCollection_shard1_replica_n1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 31 [junit4] 2> 85489 INFO (searcherExecutor-206-thread-1) [ ] o.a.s.c.SolrCore [parallelDestinationCollection_shard1_replica_n1] Registered new searcher Searcher@6fc0eb8[parallelDestinationCollection_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(8.0.0):c3)))} [junit4] 2> 85489 INFO (qtp403395034-1650) [ ] o.a.s.u.p.LogUpdateProcessorFactory [parallelDestinationCollection_shard1_replica_n1] webapp=/solr path=/update params={_stateVer_=parallelDestinationCollection:4&waitSearcher=false&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 33 [junit4] 2> 85513 INFO (qtp506020297-1638) [ ] o.a.s.c.S.Request [parallelDestinationCollection_shard2_replica_n2] webapp=/solr path=/select params={q=*:*&distrib=false&fl=id,a_s,a_i,a_f,s_multi,i_multi&sort=a_i+asc&wt=json&version=2.2} hits=2 status=0 QTime=0 [junit4] 2> 85514 INFO (qtp403395034-1630) [ ] o.a.s.c.S.Request [parallelDestinationCollection_shard1_replica_n1] webapp=/solr path=/select params={q=*:*&distrib=false&fl=id,a_s,a_i,a_f,s_multi,i_multi&sort=a_i+asc&wt=json&version=2.2} hits=3 status=0 QTime=0 [junit4] 2> 85517 INFO (qtp1314863458-1635) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=parallelDestinationCollection&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 85538 INFO (OverseerThreadFactory-190-thread-3) [ ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true [junit4] 2> 85539 INFO (qtp403395034-1646) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.parallelDestinationCollection.shard1.replica_n1, tag=null [junit4] 2> 85540 INFO (qtp403395034-1646) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@5ecd7462: rootName = solr_40385, domain = solr.core.parallelDestinationCollection.shard1.replica_n1, service url = null, agent id = null] for registry solr.core.parallelDestinationCollection.shard1.replica_n1 / com.codahale.metrics.MetricRegistry@1d2a5136 [junit4] 2> 85554 INFO (qtp403395034-1646) [ ] o.a.s.c.SolrCore [parallelDestinationCollection_shard1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@4aa65fab [junit4] 2> 85555 INFO (qtp403395034-1646) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.parallelDestinationCollection.shard1.replica_n1, tag=1252417451 [junit4] 2> 85555 INFO (qtp403395034-1646) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.parallelDestinationCollection.shard1.leader, tag=1252417451 [junit4] 2> 85557 INFO (qtp506020297-1643) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.parallelDestinationCollection.shard2.replica_n2, tag=null [junit4] 2> 85557 INFO (qtp506020297-1643) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@63d9171: rootName = solr_37067, domain = solr.core.parallelDestinationCollection.shard2.replica_n2, service url = null, agent id = null] for registry solr.core.parallelDestinationCollection.shard2.replica_n2 / com.codahale.metrics.MetricRegistry@36d5a24d [junit4] 2> 85570 INFO (qtp506020297-1643) [ ] o.a.s.c.SolrCore [parallelDestinationCollection_shard2_replica_n2] CLOSING SolrCore org.apache.solr.core.SolrCore@732b62b4 [junit4] 2> 85570 INFO (qtp506020297-1643) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.parallelDestinationCollection.shard2.replica_n2, tag=1932223156 [junit4] 2> 85570 INFO (qtp506020297-1643) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.parallelDestinationCollection.shard2.leader, tag=1932223156 [junit4] 2> 85575 INFO (qtp403395034-1646) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=parallelDestinationCollection_shard1_replica_n1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=36 [junit4] 2> 85587 INFO (qtp506020297-1643) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=parallelDestinationCollection_shard2_replica_n2&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=30 [junit4] 2> 86300 INFO (qtp1314863458-1635) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=parallelDestinationCollection&action=DELETE&wt=javabin&version=2} status=0 QTime=783 [junit4] 2> 86302 INFO (TEST-StreamExpressionTest.testParallelCommitStream-seed#[9391CF1B04EAEA56]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testParallelCommitStream [junit4] 2> 86305 INFO (OverseerCollectionConfigSetProcessor-98500542032183308-127.0.0.1:37067_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000004 doesn't exist. Requestor may have disconnected from ZooKeeper [junit4] 2> 86346 INFO (TEST-StreamExpressionTest.testParallelPriorityStream-seed#[9391CF1B04EAEA56]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testParallelPriorityStream [junit4] 2> 86353 INFO (qtp919056506-1623) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@3d425ce5[collection1_shard1_replica_n1] realtime] [junit4] 2> 86353 INFO (qtp403395034-1651) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@2257efe6[collection1_shard2_replica_n2] realtime] [junit4] 2> 86354 INFO (qtp919056506-1623) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard1_replica_n1] webapp=/solr path=/update params={update.distrib=TOLEADER&distrib.from=http://127.0.0.1:40385/solr/collection1_shard2_replica_n2/&wt=javabin&version=2}{deleteByQuery=*:* (-1576008680862646272)} 0 3 [junit4] 2> 86359 INFO (qtp403395034-1777) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008680872083456,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 86359 INFO (qtp403395034-1777) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@a2bff96 commitCommandVersion:1576008680872083456 [junit4] 2> 86359 INFO (qtp403395034-1777) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@3a1691ed[collection1_shard2_replica_n2] main] [junit4] 2> 86361 INFO (searcherExecutor-197-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard2_replica_n2] Registered new searcher Searcher@3a1691ed[collection1_shard2_replica_n2] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 86370 INFO (qtp403395034-1777) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 86370 INFO (qtp403395034-1777) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:40385/solr/collection1_shard2_replica_n2/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 11 [junit4] 2> 86371 INFO (qtp919056506-1627) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1576008680884666368,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} [junit4] 2> 86371 INFO (qtp919056506-1627) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@89dcfa6 commitCommandVersion:1576008680884666368 [junit4] 2> 86374 INFO (qtp919056506-1627) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@1568405f[collection1_shard1_replica_n1] main] [junit4] 2> 86375 INFO (qtp919056506-1627) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 86379 INFO (searcherExecutor-196-thread-1) [ ] o.a.s.c.SolrCore [collection1_shard1_replica_n1] Registered new searcher Searcher@1568405f[collection1_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 86394 INFO (qtp919056506-1627) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard1_replica_n1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:40385/solr/collection1_shard2_replica_n2/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 35 [junit4] 2> 86395 INFO (qtp403395034-1651) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/update params={_stateVer_=collection1:4&commit=true&wt=javabin&version=2}{deleteByQuery=*:* (-1576008680861597696),commit=} 0 46 [junit4] 2> 86406 INFO (qtp403395034-1650) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1_shard2_replica_n2] webapp=/solr path=/upda [...truncated too long message...] allback-795-thread-2) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 182264 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception [junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x15df1b89a030009, likely client has closed socket [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239) [junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203) [junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844) [junit4] 2> 182264 INFO (jetty-closer-778-thread-3) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@178768f9{/solr,null,UNAVAILABLE} [junit4] 2> 182264 INFO (zkCallback-799-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (2) [junit4] 2> 182264 INFO (zkCallback-797-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (2) [junit4] 2> 182266 INFO (coreCloseExecutor-388-thread-3) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.destination.shard1.replica_n1, tag=1584351941 [junit4] 2> 182266 INFO (coreCloseExecutor-388-thread-3) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@21a13c1c: rootName = solr_40385, domain = solr.core.destination.shard1.replica_n1, service url = null, agent id = null] for registry solr.core.destination.shard1.replica_n1 / com.codahale.metrics.MetricRegistry@7e50aeb5 [junit4] 2> 182270 INFO (coreCloseExecutor-388-thread-3) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.destination.shard1.leader, tag=1584351941 [junit4] 2> 182270 INFO (coreCloseExecutor-388-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.collection1.shard2.leader, tag=1279753416 [junit4] 2> 182271 INFO (coreCloseExecutor-388-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.mainCorpus.shard1.leader, tag=1004523326 [junit4] 2> 182271 WARN (zkCallback-799-thread-2) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 182271 INFO (coreCloseExecutor-388-thread-2) [ ] o.a.s.u.DirectUpdateHandler2 Committing on IndexWriter close. [junit4] 2> 182271 INFO (coreCloseExecutor-388-thread-2) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1686a7d7 commitCommandVersion:0 [junit4] 2> 182271 INFO (zkCallback-797-thread-2) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:40385_solr [junit4] 2> 182271 INFO (zkCallback-797-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1) [junit4] 2> 182271 INFO (jetty-closer-778-thread-4) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@1673b17{/solr,null,UNAVAILABLE} [junit4] 2> 182277 WARN (zkCallback-797-thread-2) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 182277 INFO (jetty-closer-778-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@115b8486{/solr,null,UNAVAILABLE} [junit4] 2> 183763 WARN (zkCallback-798-thread-2) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 183764 INFO (jetty-closer-778-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@435bff5f{/solr,null,UNAVAILABLE} [junit4] 2> 183764 ERROR (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes [junit4] 2> 183764 INFO (SUITE-StreamExpressionTest-seed#[9391CF1B04EAEA56]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:32981 32981 [junit4] 2> 189061 INFO (Thread-128) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:32981 32981 [junit4] 2> 189062 WARN (Thread-128) [ ] o.a.s.c.ZkTestServer Watch limit violations: [junit4] 2> Maximum concurrent create/delete watches above limit: [junit4] 2> [junit4] 2> 93 /solr/aliases.json [junit4] 2> 93 /solr/clusterprops.json [junit4] 2> 10 /solr/configs/conf [junit4] 2> 7 /solr/configs/ml [junit4] 2> 4 /solr/security.json [junit4] 2> [junit4] 2> Maximum concurrent data watches above limit: [junit4] 2> [junit4] 2> 93 /solr/clusterstate.json [junit4] 2> 38 /solr/collections/destinationCollection/state.json [junit4] 2> 30 /solr/collections/parallelDestinationCollection1/state.json [junit4] 2> 20 /solr/collections/destination/state.json [junit4] 2> 20 /solr/collections/parallelDestinationCollection/state.json [junit4] 2> 20 /solr/collections/mainCorpus/state.json [junit4] 2> 18 /solr/collections/workQueue/state.json [junit4] 2> 10 /solr/collections/collection1/state.json [junit4] 2> 10 /solr/collections/uknownCollection/state.json [junit4] 2> 10 /solr/collections/modelCollection/state.json [junit4] 2> 10 /solr/collections/checkpointCollection/state.json [junit4] 2> 2 /solr/overseer_elect/election/98500542032183308-127.0.0.1:37067_solr-n_0000000000 [junit4] 2> [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2> [junit4] 2> 93 /solr/live_nodes [junit4] 2> 93 /solr/collections [junit4] 2> [junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-solrj/test/J2/temp/solr.client.solrj.io.stream.StreamExpressionTest_9391CF1B04EAEA56-001 [junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {name_s=PostingsFormat(name=Memory), expr_s=PostingsFormat(name=Direct), terms_ss=PostingsFormat(name=MockRandom), field_s=PostingsFormat(name=LuceneFixedGap), join2_s=PostingsFormat(name=MockRandom), multiDefault=PostingsFormat(name=MockRandom), subject=PostingsFormat(name=MockRandom), a1_s=PostingsFormat(name=LuceneFixedGap), a2_s=PostingsFormat(name=Direct), level1_s=PostingsFormat(name=Direct), body_t=PostingsFormat(name=Memory), s_multi=PostingsFormat(name=Direct), col_s=PostingsFormat(name=LuceneFixedGap), a_ss=PostingsFormat(name=MockRandom), level2_s=PostingsFormat(name=LuceneFixedGap), a_s=PostingsFormat(name=Direct), tv_text=PostingsFormat(name=LuceneFixedGap), term_s=PostingsFormat(name=MockRandom), a_t=PostingsFormat(name=MockRandom), text_s=PostingsFormat(name=Direct), id=PostingsFormat(name=Memory), text=PostingsFormat(name=Direct), featureSet_s=PostingsFormat(name=LuceneFixedGap), checkpoint_ss=PostingsFormat(name=Memory), test_t=PostingsFormat(name=Memory), ident_s=PostingsFormat(name=LuceneFixedGap), whitetok=PostingsFormat(name=Memory), side_s=PostingsFormat(name=Memory)}, docValues:{name_s=DocValuesFormat(name=Lucene70), expr_s=DocValuesFormat(name=Lucene70), iteration_i=DocValuesFormat(name=Lucene70), terms_ss=DocValuesFormat(name=Memory), join2_s=DocValuesFormat(name=Memory), multiDefault=DocValuesFormat(name=Memory), intDefault=DocValuesFormat(name=Direct), a_f=DocValuesFormat(name=Direct), falseNegative_i=DocValuesFormat(name=Direct), a2_s=DocValuesFormat(name=Lucene70), a_i=DocValuesFormat(name=Lucene70), level1_s=DocValuesFormat(name=Lucene70), a_s=DocValuesFormat(name=Lucene70), id=DocValuesFormat(name=Lucene70), alpha_d=DocValuesFormat(name=Lucene70), i_multi=DocValuesFormat(name=Lucene70), idf_d=DocValuesFormat(name=Direct), b_ls=DocValuesFormat(name=Direct), checkpoint_ss=DocValuesFormat(name=Lucene70), ident_s=DocValuesFormat(name=Direct), order_i=DocValuesFormat(name=Memory), error_d=DocValuesFormat(name=Lucene70), truePositive_i=DocValuesFormat(name=Lucene70), side_s=DocValuesFormat(name=Lucene70), miles_i=DocValuesFormat(name=Direct), field_s=DocValuesFormat(name=Direct), price_f=DocValuesFormat(name=Memory), a1_s=DocValuesFormat(name=Direct), join1_i=DocValuesFormat(name=Lucene70), test_i=DocValuesFormat(name=Memory), join3_i=DocValuesFormat(name=Lucene70), falsePositive_i=DocValuesFormat(name=Direct), field_i=DocValuesFormat(name=Memory), s_multi=DocValuesFormat(name=Lucene70), col_s=DocValuesFormat(name=Direct), a_ss=DocValuesFormat(name=Memory), level2_s=DocValuesFormat(name=Direct), score_f=DocValuesFormat(name=Lucene70), term_s=DocValuesFormat(name=Memory), text_s=DocValuesFormat(name=Lucene70), timestamp=DocValuesFormat(name=Memory), idfs_ds=DocValuesFormat(name=Memory), weights_ds=DocValuesFormat(name=Lucene70), featureSet_s=DocValuesFormat(name=Direct), trueNegative_i=DocValuesFormat(name=Lucene70), index_i=DocValuesFormat(name=Direct), test_dt=DocValuesFormat(name=Lucene70), out_i=DocValuesFormat(name=Direct), _version_=DocValuesFormat(name=Direct)}, maxPointsInLeafNode=445, maxMBSortInHeap=5.601621738008397, sim=RandomSimilarity(queryNorm=true): {}, locale=cs-CZ, timezone=America/Coral_Harbour [junit4] 2> NOTE: Linux 4.10.0-27-generic amd64/Oracle Corporation 9 (64-bit)/cpus=8,threads=1,free=178344656,total=536870912 [junit4] 2> NOTE: All tests run in this JVM: [JdbcTest, StreamingTest, ModuloEvaluatorTest, DocumentAnalysisResponseTest, SolrSchemalessExampleTest, SolrParamTest, ConcatOperationTest, TestV2Request, SolrExceptionTest, LargeVolumeJettyTest, CloudSolrClientCacheTest, JsonValidatorTest, StreamExpressionTest] [junit4] Completed [125/135 (1!)] on J2 in 110.70s, 94 tests, 1 error <<< FAILURES! [...truncated 35681 lines...]
--------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
