You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2016/12/22 13:47:32 UTC
[JENKINS] Lucene-Solr-6.x-Solaris (64bit/jdk1.8.0) - Build # 567 -
Still Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Solaris/567/
Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: junit.framework.TestSuite.org.apache.solr.response.transform.TestSubQueryTransformerDistrib
Error Message:
1 thread leaked from SUITE scope at org.apache.solr.response.transform.TestSubQueryTransformerDistrib: 1) Thread[id=44050, name=OverseerHdfsCoreFailoverThread-97151415380148238-127.0.0.1:54762_solr-n_0000000001, state=TIMED_WAITING, group=Overseer Hdfs SolrCore Failover Thread.] at java.lang.Thread.sleep(Native Method) at org.apache.solr.cloud.OverseerAutoReplicaFailoverThread.run(OverseerAutoReplicaFailoverThread.java:139) at java.lang.Thread.run(Thread.java:745)
Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.response.transform.TestSubQueryTransformerDistrib:
1) Thread[id=44050, name=OverseerHdfsCoreFailoverThread-97151415380148238-127.0.0.1:54762_solr-n_0000000001, state=TIMED_WAITING, group=Overseer Hdfs SolrCore Failover Thread.]
at java.lang.Thread.sleep(Native Method)
at org.apache.solr.cloud.OverseerAutoReplicaFailoverThread.run(OverseerAutoReplicaFailoverThread.java:139)
at java.lang.Thread.run(Thread.java:745)
at __randomizedtesting.SeedInfo.seed([3E37933C0D6DB1E0]:0)
Build Log:
[...truncated 12527 lines...]
[junit4] Suite: org.apache.solr.response.transform.TestSubQueryTransformerDistrib
[junit4] 2> Creating dataDir: /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/init-core-data-001
[junit4] 2> 2701982 INFO (SUITE-TestSubQueryTransformerDistrib-seed#[3E37933C0D6DB1E0]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.SolrTestCaseJ4$SuppressSSL(bugUrl=None)
[junit4] 2> 2701982 INFO (SUITE-TestSubQueryTransformerDistrib-seed#[3E37933C0D6DB1E0]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 5 servers in /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001
[junit4] 2> 2701982 INFO (SUITE-TestSubQueryTransformerDistrib-seed#[3E37933C0D6DB1E0]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 2701982 INFO (Thread-5324) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 2701982 INFO (Thread-5324) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 2702082 INFO (SUITE-TestSubQueryTransformerDistrib-seed#[3E37933C0D6DB1E0]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:54264
[junit4] 2> 2702090 INFO (jetty-launcher-9833-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 2702091 INFO (jetty-launcher-9833-thread-3) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 2702091 INFO (jetty-launcher-9833-thread-5) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 2702091 INFO (jetty-launcher-9833-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 2702092 INFO (jetty-launcher-9833-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@46965ae5{/solr,null,AVAILABLE}
[junit4] 2> 2702092 INFO (jetty-launcher-9833-thread-4) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 2702094 INFO (jetty-launcher-9833-thread-4) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@75fb598{/solr,null,AVAILABLE}
[junit4] 2> 2702094 INFO (jetty-launcher-9833-thread-4) [ ] o.e.j.s.AbstractConnector Started ServerConnector@307c4efc{HTTP/1.1,[http/1.1]}{127.0.0.1:53457}
[junit4] 2> 2702094 INFO (jetty-launcher-9833-thread-4) [ ] o.e.j.s.Server Started @2706412ms
[junit4] 2> 2702094 INFO (jetty-launcher-9833-thread-4) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=53457}
[junit4] 2> 2702094 ERROR (jetty-launcher-9833-thread-4) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 2702094 INFO (jetty-launcher-9833-thread-4) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 2702095 INFO (jetty-launcher-9833-thread-4) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 2702095 INFO (jetty-launcher-9833-thread-4) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 2702095 INFO (jetty-launcher-9833-thread-4) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-12-22T13:22:34.519Z
[junit4] 2> 2702095 INFO (jetty-launcher-9833-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@69c6f573{/solr,null,AVAILABLE}
[junit4] 2> 2702097 INFO (jetty-launcher-9833-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@558cec7e{HTTP/1.1,[http/1.1]}{127.0.0.1:39331}
[junit4] 2> 2702097 INFO (jetty-launcher-9833-thread-2) [ ] o.e.j.s.Server Started @2706414ms
[junit4] 2> 2702097 INFO (jetty-launcher-9833-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=39331}
[junit4] 2> 2702097 ERROR (jetty-launcher-9833-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 2702097 INFO (jetty-launcher-9833-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 2702097 INFO (jetty-launcher-9833-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 2702097 INFO (jetty-launcher-9833-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 2702097 INFO (jetty-launcher-9833-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-12-22T13:22:34.521Z
[junit4] 2> 2702098 INFO (jetty-launcher-9833-thread-3) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@199c2541{/solr,null,AVAILABLE}
[junit4] 2> 2702099 INFO (jetty-launcher-9833-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@472ee910{HTTP/1.1,[http/1.1]}{127.0.0.1:54762}
[junit4] 2> 2702099 INFO (jetty-launcher-9833-thread-1) [ ] o.e.j.s.Server Started @2706417ms
[junit4] 2> 2702099 INFO (jetty-launcher-9833-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=54762}
[junit4] 2> 2702099 ERROR (jetty-launcher-9833-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 2702099 INFO (jetty-launcher-9833-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 2702100 INFO (jetty-launcher-9833-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 2702100 INFO (jetty-launcher-9833-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 2702100 INFO (jetty-launcher-9833-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-12-22T13:22:34.524Z
[junit4] 2> 2702100 INFO (jetty-launcher-9833-thread-5) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@7cb480ae{/solr,null,AVAILABLE}
[junit4] 2> 2702100 INFO (jetty-launcher-9833-thread-5) [ ] o.e.j.s.AbstractConnector Started ServerConnector@22cc38a{HTTP/1.1,[http/1.1]}{127.0.0.1:63027}
[junit4] 2> 2702100 INFO (jetty-launcher-9833-thread-5) [ ] o.e.j.s.Server Started @2706418ms
[junit4] 2> 2702101 INFO (jetty-launcher-9833-thread-5) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=63027}
[junit4] 2> 2702101 ERROR (jetty-launcher-9833-thread-5) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 2702101 INFO (jetty-launcher-9833-thread-5) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 2702101 INFO (jetty-launcher-9833-thread-5) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 2702101 INFO (jetty-launcher-9833-thread-3) [ ] o.e.j.s.AbstractConnector Started ServerConnector@53047469{HTTP/1.1,[http/1.1]}{127.0.0.1:63292}
[junit4] 2> 2702102 INFO (jetty-launcher-9833-thread-3) [ ] o.e.j.s.Server Started @2706420ms
[junit4] 2> 2702105 INFO (jetty-launcher-9833-thread-3) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=63292}
[junit4] 2> 2702105 ERROR (jetty-launcher-9833-thread-3) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 2702105 INFO (jetty-launcher-9833-thread-3) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 2702105 INFO (jetty-launcher-9833-thread-3) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 2702105 INFO (jetty-launcher-9833-thread-3) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 2702105 INFO (jetty-launcher-9833-thread-3) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-12-22T13:22:34.529Z
[junit4] 2> 2702103 INFO (jetty-launcher-9833-thread-5) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 2702106 INFO (jetty-launcher-9833-thread-5) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-12-22T13:22:34.530Z
[junit4] 2> 2702107 INFO (jetty-launcher-9833-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 2702109 INFO (jetty-launcher-9833-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 2702110 INFO (jetty-launcher-9833-thread-3) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 2702112 INFO (jetty-launcher-9833-thread-4) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 2702120 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 0x15926b293290004, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 2702121 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 0x15926b293290001, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 2702121 INFO (jetty-launcher-9833-thread-5) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 2702122 INFO (jetty-launcher-9833-thread-3) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 2702123 INFO (jetty-launcher-9833-thread-3) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54264/solr
[junit4] 2> 2702123 INFO (jetty-launcher-9833-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 2702124 INFO (jetty-launcher-9833-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54264/solr
[junit4] 2> 2702127 INFO (jetty-launcher-9833-thread-2) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 2702128 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 0x15926b293290003, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 2702129 INFO (jetty-launcher-9833-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54264/solr
[junit4] 2> 2702130 INFO (jetty-launcher-9833-thread-4) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 2702131 INFO (jetty-launcher-9833-thread-4) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54264/solr
[junit4] 2> 2702131 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 0x15926b293290005, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 2702134 INFO (jetty-launcher-9833-thread-5) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 2702135 INFO (jetty-launcher-9833-thread-5) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:54264/solr
[junit4] 2> 2702182 INFO (jetty-launcher-9833-thread-3) [n:127.0.0.1:63292_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:63292_solr
[junit4] 2> 2702185 INFO (jetty-launcher-9833-thread-1) [n:127.0.0.1:54762_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54762_solr
[junit4] 2> 2702185 INFO (jetty-launcher-9833-thread-3) [n:127.0.0.1:63292_solr ] o.a.s.c.Overseer Overseer (id=97151415380148236-127.0.0.1:63292_solr-n_0000000000) starting
[junit4] 2> 2702187 INFO (jetty-launcher-9833-thread-5) [n:127.0.0.1:63027_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63027_solr
[junit4] 2> 2702188 INFO (zkCallback-9856-thread-1-processing-n:127.0.0.1:63292_solr) [n:127.0.0.1:63292_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 2702191 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 2702192 INFO (zkCallback-9859-thread-1-processing-n:127.0.0.1:63027_solr) [n:127.0.0.1:63027_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 2702193 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 2702193 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 2702194 INFO (zkCallback-9856-thread-1-processing-n:127.0.0.1:63292_solr) [n:127.0.0.1:63292_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 2702203 INFO (jetty-launcher-9833-thread-3) [n:127.0.0.1:63292_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63292_solr
[junit4] 2> 2702205 INFO (zkCallback-9859-thread-1-processing-n:127.0.0.1:63027_solr) [n:127.0.0.1:63027_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (3)
[junit4] 2> 2702206 INFO (jetty-launcher-9833-thread-4) [n:127.0.0.1:53457_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53457_solr
[junit4] 2> 2702214 INFO (jetty-launcher-9833-thread-2) [n:127.0.0.1:39331_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39331_solr
[junit4] 2> 2702228 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (3)
[junit4] 2> 2702243 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (3)
[junit4] 2> 2702243 INFO (zkCallback-9856-thread-1-processing-n:127.0.0.1:63292_solr) [n:127.0.0.1:63292_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 2702259 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (4)
[junit4] 2> 2702260 INFO (zkCallback-9859-thread-1-processing-n:127.0.0.1:63027_solr) [n:127.0.0.1:63027_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (5)
[junit4] 2> 2702261 INFO (zkCallback-9856-thread-1-processing-n:127.0.0.1:63292_solr) [n:127.0.0.1:63292_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (5)
[junit4] 2> 2702261 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (5)
[junit4] 2> 2702263 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 2702263 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (5)
[junit4] 2> 2702326 INFO (jetty-launcher-9833-thread-4) [n:127.0.0.1:53457_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node5/.
[junit4] 2> 2702366 INFO (jetty-launcher-9833-thread-1) [n:127.0.0.1:54762_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node1/.
[junit4] 2> 2702386 INFO (jetty-launcher-9833-thread-3) [n:127.0.0.1:63292_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node3/.
[junit4] 2> 2702450 INFO (jetty-launcher-9833-thread-5) [n:127.0.0.1:63027_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node4/.
[junit4] 2> 2702564 INFO (jetty-launcher-9833-thread-2) [n:127.0.0.1:39331_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node2/.
[junit4] 2> 2702573 INFO (SUITE-TestSubQueryTransformerDistrib-seed#[3E37933C0D6DB1E0]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (5)
[junit4] 2> 2702575 INFO (SUITE-TestSubQueryTransformerDistrib-seed#[3E37933C0D6DB1E0]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:54264/solr ready
[junit4] 2> 2703191 INFO (qtp800207122-43884) [n:127.0.0.1:63292_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=2&property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&collection.configName=solrCloudCollectionConfig&name=people&action=CREATE&numShards=2&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 2703195 INFO (OverseerThreadFactory-9427-thread-1-processing-n:127.0.0.1:63292_solr) [n:127.0.0.1:63292_solr ] o.a.s.c.CreateCollectionCmd Create collection people
[junit4] 2> 2703307 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr ] o.a.s.h.a.CoreAdminOperation core create command property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=people_shard2_replica2&action=CREATE&numShards=2&collection=people&shard=shard2&wt=javabin&version=2
[junit4] 2> 2703307 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr ] o.a.s.h.a.CoreAdminOperation core create command property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=people_shard1_replica1&action=CREATE&numShards=2&collection=people&shard=shard1&wt=javabin&version=2
[junit4] 2> 2703308 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr ] o.a.s.h.a.CoreAdminOperation core create command property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=people_shard2_replica1&action=CREATE&numShards=2&collection=people&shard=shard2&wt=javabin&version=2
[junit4] 2> 2703311 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr ] o.a.s.h.a.CoreAdminOperation core create command property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=people_shard1_replica2&action=CREATE&numShards=2&collection=people&shard=shard1&wt=javabin&version=2
[junit4] 2> 2703428 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2703429 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2703429 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2703429 INFO (zkCallback-9856-thread-1-processing-n:127.0.0.1:63292_solr) [n:127.0.0.1:63292_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2704325 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 2704332 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 2704348 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 2704350 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 2704356 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.s.IndexSchema [people_shard2_replica2] Schema name=doc-values-for-Join
[junit4] 2> 2704361 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.s.IndexSchema [people_shard1_replica1] Schema name=doc-values-for-Join
[junit4] 2> 2704362 WARN (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.s.IndexSchema [people_shard2_replica2] default search field in schema is id. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 2704365 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.s.IndexSchema Loaded schema doc-values-for-Join/1.6 with uniqueid field id
[junit4] 2> 2704369 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.s.IndexSchema [people_shard1_replica2] Schema name=doc-values-for-Join
[junit4] 2> 2704379 WARN (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.s.IndexSchema [people_shard1_replica1] default search field in schema is id. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 2704381 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.s.IndexSchema Loaded schema doc-values-for-Join/1.6 with uniqueid field id
[junit4] 2> 2704384 WARN (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.s.IndexSchema [people_shard1_replica2] default search field in schema is id. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 2704385 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.s.IndexSchema Loaded schema doc-values-for-Join/1.6 with uniqueid field id
[junit4] 2> 2704387 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.c.CoreContainer Creating SolrCore 'people_shard1_replica1' using configuration from collection people
[junit4] 2> 2704390 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.s.IndexSchema [people_shard2_replica1] Schema name=doc-values-for-Join
[junit4] 2> 2704390 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.c.SolrCore [[people_shard1_replica1] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node5/people_shard1_replica1], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node5/./people_shard1_replica1/data/]
[junit4] 2> 2704394 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.CoreContainer Creating SolrCore 'people_shard1_replica2' using configuration from collection people
[junit4] 2> 2704393 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.CoreContainer Creating SolrCore 'people_shard2_replica2' using configuration from collection people
[junit4] 2> 2704395 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.SolrCore [[people_shard2_replica2] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node3/people_shard2_replica2], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node3/./people_shard2_replica2/data/]
[junit4] 2> 2704395 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.SolrCore [[people_shard1_replica2] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node2/people_shard1_replica2], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node2/./people_shard1_replica2/data/]
[junit4] 2> 2704409 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 2704410 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2704411 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 2704411 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2704411 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 2704412 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.s.SolrIndexSearcher Opening [Searcher@2e9111e2[people_shard2_replica2] main]
[junit4] 2> 2704412 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2704413 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 2704413 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2704414 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.s.SolrIndexSearcher Opening [Searcher@6d3d36[people_shard1_replica2] main]
[junit4] 2> 2704414 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/solrCloudCollectionConfig
[junit4] 2> 2704414 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/solrCloudCollectionConfig
[junit4] 2> 2704414 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 2704415 INFO (searcherExecutor-9440-thread-1-processing-n:127.0.0.1:63292_solr x:people_shard2_replica2 s:shard2 c:people) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.SolrCore [people_shard2_replica2] Registered new searcher Searcher@2e9111e2[people_shard2_replica2] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2704415 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1554422648630411264
[junit4] 2> 2704416 WARN (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.s.IndexSchema [people_shard2_replica1] default search field in schema is id. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 2704416 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.s.IndexSchema Loaded schema doc-values-for-Join/1.6 with uniqueid field id
[junit4] 2> 2704418 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/solrCloudCollectionConfig
[junit4] 2> 2704418 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/solrCloudCollectionConfig
[junit4] 2> 2704418 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 2704419 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1554422648634605568
[junit4] 2> 2704419 INFO (searcherExecutor-9439-thread-1-processing-n:127.0.0.1:39331_solr x:people_shard1_replica2 s:shard1 c:people) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.SolrCore [people_shard1_replica2] Registered new searcher Searcher@6d3d36[people_shard1_replica2] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2704424 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard2: total=2 found=1 timeoutin=9999ms
[junit4] 2> 2704428 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard1: total=2 found=1 timeoutin=9999ms
[junit4] 2> 2704430 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 2704430 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2704430 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.c.CoreContainer Creating SolrCore 'people_shard2_replica1' using configuration from collection people
[junit4] 2> 2704430 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.c.SolrCore [[people_shard2_replica1] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node1/people_shard2_replica1], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node1/./people_shard2_replica1/data/]
[junit4] 2> 2704431 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 2704431 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2704431 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@5eabad51[people_shard1_replica1] main]
[junit4] 2> 2704433 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/solrCloudCollectionConfig
[junit4] 2> 2704433 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/solrCloudCollectionConfig
[junit4] 2> 2704433 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 2704434 INFO (searcherExecutor-9438-thread-1-processing-n:127.0.0.1:53457_solr x:people_shard1_replica1 s:shard1 c:people) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.c.SolrCore [people_shard1_replica1] Registered new searcher Searcher@5eabad51[people_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2704434 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1554422648650334208
[junit4] 2> 2704440 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 2704440 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2704441 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 2704441 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2704441 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@4cbea620[people_shard2_replica1] main]
[junit4] 2> 2704443 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/solrCloudCollectionConfig
[junit4] 2> 2704443 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/solrCloudCollectionConfig
[junit4] 2> 2704443 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 2704443 INFO (searcherExecutor-9451-thread-1-processing-n:127.0.0.1:54762_solr x:people_shard2_replica1 s:shard2 c:people) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.c.SolrCore [people_shard2_replica1] Registered new searcher Searcher@4cbea620[people_shard2_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2704444 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1554422648660819968
[junit4] 2> 2704532 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2704532 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2704532 INFO (zkCallback-9856-thread-2-processing-n:127.0.0.1:63292_solr) [n:127.0.0.1:63292_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2704532 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2704926 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 2704926 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 2704926 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:63292/solr/people_shard2_replica2/
[junit4] 2> 2704926 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.u.PeerSync PeerSync: core=people_shard2_replica2 url=http://127.0.0.1:63292/solr START replicas=[http://127.0.0.1:54762/solr/people_shard2_replica1/] nUpdates=100
[junit4] 2> 2704926 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.u.PeerSync PeerSync: core=people_shard2_replica2 url=http://127.0.0.1:63292/solr DONE. We have no versions. sync failed.
[junit4] 2> 2704929 INFO (qtp686328333-43851) [n:127.0.0.1:54762_solr c:people s:shard2 r:core_node3 x:people_shard2_replica1] o.a.s.c.S.Request [people_shard2_replica1] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 2704929 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 2704929 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 2704929 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 2704929 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4] 2> 2704930 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:39331/solr/people_shard1_replica2/
[junit4] 2> 2704930 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.u.PeerSync PeerSync: core=people_shard1_replica2 url=http://127.0.0.1:39331/solr START replicas=[http://127.0.0.1:53457/solr/people_shard1_replica1/] nUpdates=100
[junit4] 2> 2704930 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.u.PeerSync PeerSync: core=people_shard1_replica2 url=http://127.0.0.1:39331/solr DONE. We have no versions. sync failed.
[junit4] 2> 2704932 INFO (qtp704009438-43864) [n:127.0.0.1:53457_solr c:people s:shard1 r:core_node2 x:people_shard1_replica1] o.a.s.c.S.Request [people_shard1_replica1] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 2704933 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 2704933 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4] 2> 2704936 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:63292/solr/people_shard2_replica2/ shard2
[junit4] 2> 2704938 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:39331/solr/people_shard1_replica2/ shard1
[junit4] 2> 2705044 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2705044 INFO (zkCallback-9856-thread-2-processing-n:127.0.0.1:63292_solr) [n:127.0.0.1:63292_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2705044 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2705044 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2705088 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 2705089 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 2705090 INFO (qtp800207122-43885) [n:127.0.0.1:63292_solr c:people s:shard2 x:people_shard2_replica2] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=people_shard2_replica2&action=CREATE&numShards=2&collection=people&shard=shard2&wt=javabin&version=2} status=0 QTime=1783
[junit4] 2> 2705092 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:people s:shard1 x:people_shard1_replica2] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=people_shard1_replica2&action=CREATE&numShards=2&collection=people&shard=shard1&wt=javabin&version=2} status=0 QTime=1782
[junit4] 2> 2705196 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2705197 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2705197 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2705197 INFO (zkCallback-9856-thread-2-processing-n:127.0.0.1:63292_solr) [n:127.0.0.1:63292_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2705450 INFO (qtp704009438-43863) [n:127.0.0.1:53457_solr c:people s:shard1 x:people_shard1_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=people_shard1_replica1&action=CREATE&numShards=2&collection=people&shard=shard1&wt=javabin&version=2} status=0 QTime=2144
[junit4] 2> 2705453 INFO (qtp686328333-43849) [n:127.0.0.1:54762_solr c:people s:shard2 x:people_shard2_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=people_shard2_replica1&action=CREATE&numShards=2&collection=people&shard=shard2&wt=javabin&version=2} status=0 QTime=2146
[junit4] 2> 2705457 INFO (qtp800207122-43884) [n:127.0.0.1:63292_solr ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
[junit4] 2> 2705557 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2705558 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2705558 INFO (zkCallback-9856-thread-2-processing-n:127.0.0.1:63292_solr) [n:127.0.0.1:63292_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2705558 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/people/state.json] for collection [people] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2706459 INFO (qtp800207122-43884) [n:127.0.0.1:63292_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=2&property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&collection.configName=solrCloudCollectionConfig&name=people&action=CREATE&numShards=2&wt=javabin&version=2} status=0 QTime=3270
[junit4] 2> 2706462 INFO (qtp800207122-43887) [n:127.0.0.1:63292_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=2&property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&collection.configName=solrCloudCollectionConfig&name=departments&action=CREATE&numShards=2&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 2706466 INFO (OverseerThreadFactory-9427-thread-2-processing-n:127.0.0.1:63292_solr) [n:127.0.0.1:63292_solr ] o.a.s.c.CreateCollectionCmd Create collection departments
[junit4] 2> 2706467 INFO (OverseerCollectionConfigSetProcessor-97151415380148236-127.0.0.1:63292_solr-n_0000000000) [n:127.0.0.1:63292_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 2706681 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr ] o.a.s.h.a.CoreAdminOperation core create command property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=departments_shard2_replica2&action=CREATE&numShards=2&collection=departments&shard=shard2&wt=javabin&version=2
[junit4] 2> 2706681 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr ] o.a.s.h.a.CoreAdminOperation core create command property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=departments_shard1_replica1&action=CREATE&numShards=2&collection=departments&shard=shard1&wt=javabin&version=2
[junit4] 2> 2706682 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr ] o.a.s.h.a.CoreAdminOperation core create command property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=departments_shard1_replica2&action=CREATE&numShards=2&collection=departments&shard=shard1&wt=javabin&version=2
[junit4] 2> 2706681 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr ] o.a.s.h.a.CoreAdminOperation core create command property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=departments_shard2_replica1&action=CREATE&numShards=2&collection=departments&shard=shard2&wt=javabin&version=2
[junit4] 2> 2706797 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2706797 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2706797 INFO (zkCallback-9859-thread-1-processing-n:127.0.0.1:63027_solr) [n:127.0.0.1:63027_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2706797 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2707696 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 2707698 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 2707715 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 2707718 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 2707726 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.s.IndexSchema [departments_shard2_replica2] Schema name=doc-values-for-Join
[junit4] 2> 2707726 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.s.IndexSchema [departments_shard2_replica1] Schema name=doc-values-for-Join
[junit4] 2> 2707727 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.s.IndexSchema [departments_shard1_replica1] Schema name=doc-values-for-Join
[junit4] 2> 2707758 WARN (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.s.IndexSchema [departments_shard2_replica2] default search field in schema is id. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 2707758 WARN (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.s.IndexSchema [departments_shard2_replica1] default search field in schema is id. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 2707759 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.s.IndexSchema Loaded schema doc-values-for-Join/1.6 with uniqueid field id
[junit4] 2> 2707759 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.s.IndexSchema Loaded schema doc-values-for-Join/1.6 with uniqueid field id
[junit4] 2> 2707766 WARN (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.s.IndexSchema [departments_shard1_replica1] default search field in schema is id. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 2707767 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.s.IndexSchema Loaded schema doc-values-for-Join/1.6 with uniqueid field id
[junit4] 2> 2707767 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.s.IndexSchema [departments_shard1_replica2] Schema name=doc-values-for-Join
[junit4] 2> 2707774 WARN (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.s.IndexSchema [departments_shard1_replica2] default search field in schema is id. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 2707775 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.s.IndexSchema Loaded schema doc-values-for-Join/1.6 with uniqueid field id
[junit4] 2> 2707777 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.c.CoreContainer Creating SolrCore 'departments_shard2_replica2' using configuration from collection departments
[junit4] 2> 2707777 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.c.SolrCore [[departments_shard2_replica2] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node1/departments_shard2_replica2], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node1/./departments_shard2_replica2/data/]
[junit4] 2> 2707781 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.CoreContainer Creating SolrCore 'departments_shard2_replica1' using configuration from collection departments
[junit4] 2> 2707781 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.SolrCore [[departments_shard2_replica1] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node4/departments_shard2_replica1], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node4/./departments_shard2_replica1/data/]
[junit4] 2> 2707786 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 2707786 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2707787 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 2707787 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2707787 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.s.SolrIndexSearcher Opening [Searcher@299bb69c[departments_shard2_replica2] main]
[junit4] 2> 2707789 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 2707789 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2707790 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 2707790 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2707791 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@261ae6d2[departments_shard2_replica1] main]
[junit4] 2> 2707794 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.CoreContainer Creating SolrCore 'departments_shard1_replica2' using configuration from collection departments
[junit4] 2> 2707794 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.SolrCore [[departments_shard1_replica2] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node5/departments_shard1_replica2], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node5/./departments_shard1_replica2/data/]
[junit4] 2> 2707797 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/solrCloudCollectionConfig
[junit4] 2> 2707798 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/solrCloudCollectionConfig
[junit4] 2> 2707798 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 2707798 INFO (searcherExecutor-9459-thread-1-processing-n:127.0.0.1:63027_solr x:departments_shard2_replica1 s:shard2 c:departments) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.SolrCore [departments_shard2_replica1] Registered new searcher Searcher@261ae6d2[departments_shard2_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2707798 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1554422652177743872
[junit4] 2> 2707804 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 2707804 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2707805 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 2707805 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard2: total=2 found=1 timeoutin=9999ms
[junit4] 2> 2707805 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2707806 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.s.SolrIndexSearcher Opening [Searcher@e460986[departments_shard1_replica2] main]
[junit4] 2> 2707806 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/solrCloudCollectionConfig
[junit4] 2> 2707807 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/solrCloudCollectionConfig
[junit4] 2> 2707807 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 2707807 INFO (searcherExecutor-9458-thread-1-processing-n:127.0.0.1:54762_solr x:departments_shard2_replica2 s:shard2 c:departments) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.c.SolrCore [departments_shard2_replica2] Registered new searcher Searcher@299bb69c[departments_shard2_replica2] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2707807 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1554422652187181056
[junit4] 2> 2707807 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/solrCloudCollectionConfig
[junit4] 2> 2707807 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/solrCloudCollectionConfig
[junit4] 2> 2707808 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 2707808 INFO (searcherExecutor-9468-thread-1-processing-n:127.0.0.1:53457_solr x:departments_shard1_replica2 s:shard1 c:departments) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.SolrCore [departments_shard1_replica2] Registered new searcher Searcher@e460986[departments_shard1_replica2] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2707808 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1554422652188229632
[junit4] 2> 2707812 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.c.CoreContainer Creating SolrCore 'departments_shard1_replica1' using configuration from collection departments
[junit4] 2> 2707812 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.c.SolrCore [[departments_shard1_replica1] ] Opening new SolrCore at [/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node2/departments_shard1_replica1], dataDir=[/export/home/jenkins/workspace/Lucene-Solr-6.x-Solaris/solr/build/solr-core/test/J0/temp/solr.response.transform.TestSubQueryTransformerDistrib_3E37933C0D6DB1E0-001/tempDir-001/node2/./departments_shard1_replica1/data/]
[junit4] 2> 2707816 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard1: total=2 found=1 timeoutin=9999ms
[junit4] 2> 2707823 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 2707823 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2707824 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 2707824 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2707825 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@37e63ae2[departments_shard1_replica1] main]
[junit4] 2> 2707827 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/solrCloudCollectionConfig
[junit4] 2> 2707827 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/solrCloudCollectionConfig
[junit4] 2> 2707827 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 2707827 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1554422652208152576
[junit4] 2> 2707830 INFO (searcherExecutor-9473-thread-1-processing-n:127.0.0.1:39331_solr x:departments_shard1_replica1 s:shard1 c:departments) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.c.SolrCore [departments_shard1_replica1] Registered new searcher Searcher@37e63ae2[departments_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2707921 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2707921 INFO (zkCallback-9859-thread-1-processing-n:127.0.0.1:63027_solr) [n:127.0.0.1:63027_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2707921 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2707921 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708310 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 2708310 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 2708310 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:63027/solr/departments_shard2_replica1/
[junit4] 2> 2708310 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.u.PeerSync PeerSync: core=departments_shard2_replica1 url=http://127.0.0.1:63027/solr START replicas=[http://127.0.0.1:54762/solr/departments_shard2_replica2/] nUpdates=100
[junit4] 2> 2708311 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.u.PeerSync PeerSync: core=departments_shard2_replica1 url=http://127.0.0.1:63027/solr DONE. We have no versions. sync failed.
[junit4] 2> 2708314 INFO (qtp686328333-43855) [n:127.0.0.1:54762_solr c:departments s:shard2 r:core_node1 x:departments_shard2_replica2] o.a.s.c.S.Request [departments_shard2_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 2708314 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 2708314 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4] 2> 2708317 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 2708317 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 2708318 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:53457/solr/departments_shard1_replica2/
[junit4] 2> 2708318 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.u.PeerSync PeerSync: core=departments_shard1_replica2 url=http://127.0.0.1:53457/solr START replicas=[http://127.0.0.1:39331/solr/departments_shard1_replica1/] nUpdates=100
[junit4] 2> 2708318 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.u.PeerSync PeerSync: core=departments_shard1_replica2 url=http://127.0.0.1:53457/solr DONE. We have no versions. sync failed.
[junit4] 2> 2708319 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:63027/solr/departments_shard2_replica1/ shard2
[junit4] 2> 2708321 INFO (qtp796872580-43873) [n:127.0.0.1:39331_solr c:departments s:shard1 r:core_node2 x:departments_shard1_replica1] o.a.s.c.S.Request [departments_shard1_replica1] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=1
[junit4] 2> 2708321 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 2708321 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4] 2> 2708326 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:53457/solr/departments_shard1_replica2/ shard1
[junit4] 2> 2708430 INFO (zkCallback-9859-thread-1-processing-n:127.0.0.1:63027_solr) [n:127.0.0.1:63027_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708430 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708430 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708430 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708473 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 2708475 INFO (qtp1504601955-43894) [n:127.0.0.1:63027_solr c:departments s:shard2 x:departments_shard2_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=departments_shard2_replica1&action=CREATE&numShards=2&collection=departments&shard=shard2&wt=javabin&version=2} status=0 QTime=1795
[junit4] 2> 2708478 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 2708481 INFO (qtp704009438-43862) [n:127.0.0.1:53457_solr c:departments s:shard1 x:departments_shard1_replica2] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=departments_shard1_replica2&action=CREATE&numShards=2&collection=departments&shard=shard1&wt=javabin&version=2} status=0 QTime=1800
[junit4] 2> 2708584 INFO (zkCallback-9859-thread-1-processing-n:127.0.0.1:63027_solr) [n:127.0.0.1:63027_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708585 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708585 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708585 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708821 INFO (qtp686328333-43854) [n:127.0.0.1:54762_solr c:departments s:shard2 x:departments_shard2_replica2] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=departments_shard2_replica2&action=CREATE&numShards=2&collection=departments&shard=shard2&wt=javabin&version=2} status=0 QTime=2141
[junit4] 2> 2708838 INFO (qtp796872580-43875) [n:127.0.0.1:39331_solr c:departments s:shard1 x:departments_shard1_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&qt=/admin/cores&collection.configName=solrCloudCollectionConfig&newCollection=true&name=departments_shard1_replica1&action=CREATE&numShards=2&collection=departments&shard=shard1&wt=javabin&version=2} status=0 QTime=2157
[junit4] 2> 2708841 INFO (qtp800207122-43887) [n:127.0.0.1:63292_solr ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
[junit4] 2> 2708944 INFO (zkCallback-9855-thread-1-processing-n:127.0.0.1:39331_solr) [n:127.0.0.1:39331_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708944 INFO (zkCallback-9859-thread-1-processing-n:127.0.0.1:63027_solr) [n:127.0.0.1:63027_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708945 INFO (zkCallback-9857-thread-1-processing-n:127.0.0.1:53457_solr) [n:127.0.0.1:53457_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2708945 INFO (zkCallback-9858-thread-1-processing-n:127.0.0.1:54762_solr) [n:127.0.0.1:54762_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/departments/state.json] for collection [departments] has occurred - updating... (live nodes size: [5])
[junit4] 2> 2709843 INFO (qtp800207122-43887) [n:127.0.0.1:63292_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=2&property.config=solrconfig-doctransformers.xml&property.schema=schema-docValuesJoin.xml&collection.configName=solrCloudCollectionConfig&name=departments&action=CREATE&numShards=2&wt=javabin&version=2} status=0 QTime=3382
[junit4] 2> 2709844 INFO (SUITE-TestSubQueryTransformerDistrib-seed#[3E37933C0D6DB1E0]-worker) [ ] o.a.s.c.AbstractDistribZkTestBase Wait for recoveries to finish - collection: people failOnTimeout:true timeout (sec):30
[junit4] 1> -
[junit4] 1> replica:core_node2 rstate:active live:true
[junit4] 1> replica:core_node4 rstate:active live:true
[junit4] 1> replica:core_node1 rstate:active live:true
[junit4] 1> replica:core_node3 rstate:active live:true
[junit4] 1> no one is recoverying
[junit4] 2> 2709844 INFO (SUITE-TestSubQueryTransformerDistrib-seed#[3E37933C0D6DB1E0]-worker) [ ] o.a.s.c.AbstractDistribZkTestBase Recoveries finished - collection: people
[junit4] 2> 2709844 INFO (SUITE-TestSubQueryTransformerDistrib-seed#[3E37933C0D6DB1E0]-worker) [ ] o.a.s.c.AbstractDistribZkTestBase Wait for recoveries to finish - collection: departments failOnTimeout:true timeout (sec):30
[junit4] 2> 2709845 INFO (SUITE-TestSubQueryTransformerDistrib-seed#[3E37933C0D6DB1E0]-worker) [ ] o.a.s.c.AbstractDistribZkTestBase Recoveries finished - collection: departments
[junit4] 2> 2709939 INFO (TEST-TestSubQueryTransformerDistrib.test-seed#[3E37933C0D6DB1E0]) [ ] o.a.s.SolrTestCaseJ4 ###Starting test
[junit4] 2> 2709952 INFO (qtp704009438-43865) [n:127.0.0.1:53457_solr c:people s:shard1 r:core_node2 x:people_shard1_replica1] o.a.s.u.p.LogUpdateProcessorFactory [people_shard1_replica1] webapp=/solr path=/update params={update.distrib=FROMLEADER&_version_=-1554422654425890816&distrib.from=http://127.0.0.1:39331/solr/people_shard1_replica2/&wt=javabin&version=2}{deleteByQuery=*:* (-1554422654425890816)} 0 4
[junit4] 2> 2709953 INFO (qtp686328333-43851) [n:127.0.0.1:54762_solr c:people s:shard2 r:core_node3 x:people_shard2_replica1] o.a.s.u.p.LogUpdateProcessorFactory [people_shard2_replica1] webapp=/solr path=/update params={update.distrib=FROMLEADER&_version_=-1554422654427987968&distrib.from=http://127.0.0.1:63292/solr/people_shard2_replica2/&wt=javabin&version=2}{deleteByQuery=*:* (-1554422654427987968)} 0 3
[junit4] 2> 2709953 INFO (qtp800207122-43886) [n:127.0.0.1:63292_solr c:people s:shard2 r:core_node
[...truncated too long message...]
Overseer Overseer Loop exiting : 127.0.0.1:54762_solr
[junit4] 2> 2716617 INFO (Thread-5324) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:54264 54264
[junit4] 2> 2716618 WARN (Thread-5324) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 6 /solr/aliases.json
[junit4] 2> 6 /solr/clusterprops.json
[junit4] 2> 5 /solr/security.json
[junit4] 2> 5 /solr/configs/solrCloudCollectionConfig
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 6 /solr/clusterstate.json
[junit4] 2> 4 /solr/collections/departments/state.json
[junit4] 2> 4 /solr/collections/people/state.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 20 /solr/overseer/queue
[junit4] 2> 6 /solr/live_nodes
[junit4] 2> 6 /solr/collections
[junit4] 2> 5 /solr/overseer/queue-work
[junit4] 2>
[junit4] 2> 2716619 INFO (SUITE-TestSubQueryTransformerDistrib-seed#[3E37933C0D6DB1E0]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> Dec 22, 2016 1:22:49 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s).
[junit4] 2> Dec 22, 2016 1:23:09 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> SEVERE: 1 thread leaked from SUITE scope at org.apache.solr.response.transform.TestSubQueryTransformerDistrib:
[junit4] 2> 1) Thread[id=44050, name=OverseerHdfsCoreFailoverThread-97151415380148238-127.0.0.1:54762_solr-n_0000000001, state=TIMED_WAITING, group=Overseer Hdfs SolrCore Failover Thread.]
[junit4] 2> at java.lang.Thread.sleep(Native Method)
[junit4] 2> at org.apache.solr.cloud.OverseerAutoReplicaFailoverThread.run(OverseerAutoReplicaFailoverThread.java:139)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> Dec 22, 2016 1:23:09 PM com.carrotsearch.randomizedtesting.ThreadLeakControl tryToInterruptAll
[junit4] 2> INFO: Starting to interrupt leaked threads:
[junit4] 2> 1) Thread[id=44050, name=OverseerHdfsCoreFailoverThread-97151415380148238-127.0.0.1:54762_solr-n_0000000001, state=TIMED_WAITING, group=Overseer Hdfs SolrCore Failover Thread.]
[junit4] 2> Dec 22, 2016 1:23:09 PM com.carrotsearch.randomizedtesting.ThreadLeakControl tryToInterruptAll
[junit4] 2> INFO: All leaked threads terminated.
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene62), sim=RandomSimilarity(queryNorm=true,coord=no): {}, locale=mt-MT, timezone=America/Argentina/San_Juan
[junit4] 2> NOTE: SunOS 5.11 amd64/Oracle Corporation 1.8.0_112 (64-bit)/cpus=3,threads=1,free=192654808,total=518979584
[junit4] 2> NOTE: All tests run in this JVM: [HdfsRecoveryZkTest, TestComplexPhraseQParserPlugin, TestDynamicFieldResource, TestHighlightDedupGrouping, TestBackupRepositoryFactory, BadComponentTest, TestFunctionQuery, TestSweetSpotSimilarityFactory, TestConfigSetsAPIExclusivity, ReplaceNodeTest, QueryEqualityTest, SOLR749Test, ZkStateWriterTest, TestPKIAuthenticationPlugin, ShufflingReplicaListTransformerTest, TestSolrIndexConfig, TestMissingGroups, TestStressReorder, TestGraphMLResponseWriter, ConcurrentDeleteAndCreateCollectionTest, TestConfigSets, TestFaceting, TestAnalyzedSuggestions, SolrPluginUtilsTest, TestDistributedSearch, SuggestComponentContextFilterQueryTest, MergeStrategyTest, SpatialFilterTest, TestManagedResource, TestUnifiedSolrHighlighter, TestRestManager, PathHierarchyTokenizerFactoryTest, TimeZoneUtilsTest, TestBlendedInfixSuggestions, TestCustomStream, TestSolrCloudWithKerberosAlt, CustomCollectionTest, RecoveryAfterSoftCommitTest, LeaderFailoverAfterPartitionTest, CollectionsAPIAsyncDistributedZkTest, TestPerFieldSimilarity, TestExactSharedStatsCache, TestCoreContainer, TlogReplayBufferedWhileIndexingTest, ZkCLITest, StatsReloadRaceTest, ZkNodePropsTest, OutputWriterTest, TestWordDelimiterFilterFactory, TestFastOutputStream, TestLeaderElectionWithEmptyReplica, TestInitQParser, ClassificationUpdateProcessorFactoryTest, TestSQLHandler, TestCSVLoader, SharedFSAutoReplicaFailoverUtilsTest, DeleteReplicaTest, TestSchemaManager, BaseCdcrDistributedZkTest, TestCloudPivotFacet, TestFieldCacheSanityChecker, JSONWriterTest, TestReloadAndDeleteDocs, HttpPartitionTest, AddSchemaFieldsUpdateProcessorFactoryTest, SolrRequestParserTest, DistanceUnitsTest, TestClusterStateMutator, LeaderInitiatedRecoveryOnCommitTest, ShardSplitTest, HdfsSyncSliceTest, QueryElevationComponentTest, DocValuesTest, TestSizeLimitedDistributedMap, MigrateRouteKeyTest, SortSpecParsingTest, TestReRankQParserPlugin, AnalyticsQueryTest, TestLFUCache, SuggesterFSTTest, CoreAdminCreateDiscoverTest, TestSolrJ, ZkControllerTest, TestReplicaProperties, HdfsNNFailoverTest, TestBinaryResponseWriter, JavabinLoaderTest, SolrTestCaseJ4Test, TestCloudDeleteByQuery, TestCollationField, HardAutoCommitTest, DateFieldTest, BlobRepositoryCloudTest, PrimitiveFieldTypeTest, TestNonDefinedSimilarityFactory, DistribDocExpirationUpdateProcessorTest, TestExportWriter, TestImplicitCoreProperties, DistributedFacetPivotSmallAdvancedTest, DateRangeFieldTest, TestTolerantSearch, MultiTermTest, BlockJoinFacetRandomTest, TestComponentsName, SynonymTokenizerTest, TestStressLucene, BasicDistributedZkTest, TestJmxIntegration, TemplateUpdateProcessorTest, TestDocBasedVersionConstraints, TestInitParams, BufferStoreTest, TestBinaryField, TestDistributedStatsComponentCardinality, TestPivotHelperCode, TestJsonFacets, ClusterStateUpdateTest, TestStressVersions, TestLeaderInitiatedRecoveryThread, TestSha256AuthenticationProvider, DistributedFacetPivotLargeTest, TestOrdValues, DocumentAnalysisRequestHandlerTest, TestClassicSimilarityFactory, CloudExitableDirectoryReaderTest, OutOfBoxZkACLAndCredentialsProvidersTest, HdfsBasicDistributedZkTest, LeaderElectionTest, TestSolrQueryParserDefaultOperatorResource, TestPerFieldSimilarityWithDefaultOverride, BlockCacheTest, SampleTest, JSONWriterTest, ResponseLogComponentTest, TestStressCloudBlindAtomicUpdates, CdcrRequestHandlerTest, TestXIncludeConfig, FileUtilsTest, ActionThrottleTest, TestExtendedDismaxParser, EnumFieldTest, SolrXmlInZkTest, TestRandomCollapseQParserPlugin, SystemInfoHandlerTest, ClassificationUpdateProcessorTest, XsltUpdateRequestHandlerTest, CurrencyFieldXmlFileTest, TestDefaultSearchFieldResource, BitVectorTest, TestHashPartitioner, TestCursorMarkWithoutUniqueKey, TestLRUCache, PreAnalyzedFieldManagedSchemaCloudTest, TestFieldCacheWithThreads, PrimUtilsTest, DocExpirationUpdateProcessorFactoryTest, SyncSliceTest, TestPostingsSolrHighlighter, HdfsChaosMonkeySafeLeaderTest, TestUniqueKeyFieldResource, DistributedSpellCheckComponentTest, TestSystemIdResolver, TestSuggestSpellingConverter, SpellingQueryConverterTest, DOMUtilTest, RAMDirectoryFactoryTest, TestUtils, TestDocumentBuilder, SliceStateTest, UUIDFieldTest, CircularListTest, DistributedMLTComponentTest, TestRTGBase, CursorPagingTest, TestEmbeddedSolrServerConstructors, TestJettySolrRunner, AssignTest, CdcrBootstrapTest, CollectionStateFormat2Test, ConnectionManagerTest, DeleteInactiveReplicaTest, DeleteStatusTest, DistribCursorPagingTest, LeaderFailureAfterFreshStartTest, LeaderInitiatedRecoveryOnShardRestartTest, MultiThreadedOCPTest, OverriddenZkACLAndCredentialsProvidersTest, OverseerModifyCollectionTest, OverseerTaskQueueTest, ReplicationFactorTest, RestartWhileUpdatingTest, RollingRestartTest, TestCloudRecovery, TestConfigSetsAPI, TestCryptoKeys, TestExclusionRuleCollectionAccess, TestLocalFSCloudBackupRestore, TestLockTree, TestMiniSolrCloudClusterSSL, TestRandomRequestDistribution, TestSSLRandomization, TestShortCircuitedRequests, TestStressLiveNodes, VMParamsZkACLAndCredentialsProvidersTest, HdfsCollectionsAPIDistributedZkTest, HdfsRestartWhileUpdatingTest, HdfsTlogReplayBufferedWhileIndexingTest, HdfsUnloadDistributedZkTest, HdfsWriteToMultipleCollectionsTest, StressHdfsTest, CachingDirectoryFactoryTest, TestConfigOverlay, TestConfigSetImmutable, TestCorePropertiesReload, TestShardHandlerFactory, TestSolrConfigHandler, TestSolrCoreSnapshots, RequestLoggingTest, TestBlobHandler, TestHdfsBackupRestoreCore, TestSQLHandlerNonCloud, TestSolrConfigHandlerCloud, WrapperMergePolicyFactoryTest, TestIntervalFaceting, TestMacroExpander, TestMacros, SmileWriterTest, TestBinaryResponseWriter, TestCustomDocTransformer, TestGeoJSONResponseWriter, TestJavabinTupleStreamParser, TestPushWriter, TestRawTransformer, TestSolrQueryResponse, TestChildDocTransformer, TestSubQueryTransformerCrossCore, TestSubQueryTransformerDistrib]
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestSubQueryTransformerDistrib -Dtests.seed=3E37933C0D6DB1E0 -Dtests.slow=true -Dtests.locale=mt-MT -Dtests.timezone=America/Argentina/San_Juan -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] ERROR 0.00s J0 | TestSubQueryTransformerDistrib (suite) <<<
[junit4] > Throwable #1: com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.response.transform.TestSubQueryTransformerDistrib:
[junit4] > 1) Thread[id=44050, name=OverseerHdfsCoreFailoverThread-97151415380148238-127.0.0.1:54762_solr-n_0000000001, state=TIMED_WAITING, group=Overseer Hdfs SolrCore Failover Thread.]
[junit4] > at java.lang.Thread.sleep(Native Method)
[junit4] > at org.apache.solr.cloud.OverseerAutoReplicaFailoverThread.run(OverseerAutoReplicaFailoverThread.java:139)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] > at __randomizedtesting.SeedInfo.seed([3E37933C0D6DB1E0]:0)
[junit4] Completed [583/665 (1!)] on J0 in 34.90s, 1 test, 1 error <<< FAILURES!
[...truncated 62684 lines...]