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 2013/06/30 15:13:53 UTC
[JENKINS] Lucene-Solr-trunk-Windows (64bit/jdk1.7.0_25) - Build #
2988 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/2988/
Java: 64bit/jdk1.7.0_25 -XX:+UseCompressedOops -XX:+UseParallelGC
2 tests failed.
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.BasicDistributedZkTest
Error Message:
1 thread leaked from SUITE scope at org.apache.solr.cloud.BasicDistributedZkTest: 1) Thread[id=438, name=recoveryCmdExecutor-179-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest] at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method) at java.net.DualStackPlainSocketImpl.socketConnect(DualStackPlainSocketImpl.java:85) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:172) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) at java.net.Socket.connect(Socket.java:579) at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127) at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180) at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294) at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645) at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180) at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724)
Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.BasicDistributedZkTest:
1) Thread[id=438, name=recoveryCmdExecutor-179-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method)
at java.net.DualStackPlainSocketImpl.socketConnect(DualStackPlainSocketImpl.java:85)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:172)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:579)
at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:724)
at __randomizedtesting.SeedInfo.seed([53111398A2E0B953]:0)
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.BasicDistributedZkTest
Error Message:
There are still zombie threads that couldn't be terminated: 1) Thread[id=438, name=recoveryCmdExecutor-179-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest] at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method) at java.net.DualStackPlainSocketImpl.socketConnect(DualStackPlainSocketImpl.java:85) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:172) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) at java.net.Socket.connect(Socket.java:579) at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127) at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180) at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294) at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645) at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180) at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724)
Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
1) Thread[id=438, name=recoveryCmdExecutor-179-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method)
at java.net.DualStackPlainSocketImpl.socketConnect(DualStackPlainSocketImpl.java:85)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:172)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:579)
at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:724)
at __randomizedtesting.SeedInfo.seed([53111398A2E0B953]:0)
Build Log:
[...truncated 9162 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest
[junit4:junit4] 2> 19119 T96 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /n_/
[junit4:junit4] 2> 19131 T96 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\solrtest-BasicDistributedZkTest-1372597730232
[junit4:junit4] 2> 19139 T96 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 19144 T97 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 19362 T96 oasc.ZkTestServer.run start zk server on port:51664
[junit4:junit4] 2> 19502 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 19584 T103 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4c8723cf name:ZooKeeperConnection Watcher:127.0.0.1:51664 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 19585 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 19589 T96 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 19667 T98 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f95333c890000, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 19669 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 19672 T105 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13c77dd0 name:ZooKeeperConnection Watcher:127.0.0.1:51664/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 19672 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 19683 T96 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 19692 T96 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 19698 T96 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 19703 T96 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 19710 T96 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 19712 T96 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 19723 T96 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 19724 T96 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 19731 T96 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 19732 T96 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 19739 T96 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 19739 T96 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 19747 T96 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 19748 T96 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 19759 T96 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 19760 T96 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 19767 T96 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 19768 T96 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 19779 T96 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 19780 T96 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 19785 T96 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 19786 T96 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 20501 T96 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 20709 T96 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51671
[junit4:junit4] 2> 20747 T96 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 20747 T96 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 20748 T96 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372597730898
[junit4:junit4] 2> 20748 T96 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372597730898\solr.xml
[junit4:junit4] 2> 20748 T96 oasc.CoreContainer.<init> New CoreContainer 261014678
[junit4:junit4] 2> 20751 T96 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372597730898\'
[junit4:junit4] 2> 20751 T96 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372597730898\'
[junit4:junit4] 2> 20904 T96 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 20905 T96 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 20905 T96 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 20906 T96 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 20906 T96 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 20907 T96 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 20907 T96 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 20907 T96 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 20908 T96 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 20908 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 20920 T96 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 20921 T96 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51664/solr
[junit4:junit4] 2> 20949 T96 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 20950 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 20966 T117 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7cef4e36 name:ZooKeeperConnection Watcher:127.0.0.1:51664 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 20967 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 20978 T98 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f95333c890002, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 20988 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 21029 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 21033 T119 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3676fc91 name:ZooKeeperConnection Watcher:127.0.0.1:51664/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 21033 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 21044 T96 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 21066 T96 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 21087 T96 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 21094 T96 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51671_n_
[junit4:junit4] 2> 21103 T96 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51671_n_
[junit4:junit4] 2> 21110 T96 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 21136 T96 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 21144 T96 oasc.Overseer.start Overseer (id=89954564862181379-127.0.0.1:51671_n_-n_0000000000) starting
[junit4:junit4] 2> 21171 T96 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 21196 T96 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 21198 T121 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 21204 T96 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 21208 T96 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 21230 T120 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 21244 T122 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 21245 T122 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 21248 T122 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 22872 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22882 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51671_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51671/n_"}
[junit4:junit4] 2> 22883 T120 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 22909 T120 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 22955 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 23404 T122 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 23404 T122 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372597730898\collection1
[junit4:junit4] 2> 23406 T122 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 23409 T122 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 23410 T122 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 23419 T122 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372597730898\collection1\'
[junit4:junit4] 2> 23426 T122 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372597730898/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 23430 T122 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372597730898/collection1/lib/README' to classloader
[junit4:junit4] 2> 23519 T122 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 23594 T122 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 23598 T122 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 23630 T122 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 24483 T122 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 24497 T122 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 24501 T122 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 24539 T122 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 24546 T122 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 24554 T122 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 24556 T122 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 24557 T122 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 24557 T122 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 24560 T122 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 24560 T122 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 24560 T122 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 24561 T122 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372597730898\collection1\, dataDir=.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/control/data\
[junit4:junit4] 2> 24565 T122 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4ffdd6db
[junit4:junit4] 2> 24567 T122 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/control/data\
[junit4:junit4] 2> 24567 T122 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/control/data\index/
[junit4:junit4] 2> 24567 T122 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 24569 T122 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/control/data\index
[junit4:junit4] 2> 24579 T122 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30aefbe1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682ec68b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 24579 T122 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 24631 T122 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 24631 T122 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 24632 T122 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 24633 T122 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 24633 T122 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 24634 T122 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 24634 T122 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 24634 T122 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 24635 T122 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 24646 T122 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 24653 T122 oass.SolrIndexSearcher.<init> Opening Searcher@a90eb7d main
[junit4:junit4] 2> 24655 T122 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 24655 T122 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 24660 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a90eb7d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 24663 T122 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 24663 T122 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51671/n_ collection:control_collection shard:shard1
[junit4:junit4] 2> 24676 T122 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 24686 T122 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 24733 T122 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4] 2> 24749 T122 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 24749 T122 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 24750 T122 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51671/n_/collection1/
[junit4:junit4] 2> 24751 T122 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 24752 T122 oasc.SyncStrategy.syncToMe http://127.0.0.1:51671/n_/collection1/ has no replicas
[junit4:junit4] 2> 24752 T122 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51671/n_/collection1/ shard1
[junit4:junit4] 2> 24753 T122 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 26234 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 26292 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 26323 T122 oasc.ZkController.register We are http://127.0.0.1:51671/n_/collection1/ and leader is http://127.0.0.1:51671/n_/collection1/
[junit4:junit4] 2> 26323 T122 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51671/n_
[junit4:junit4] 2> 26323 T122 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 26325 T122 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 26325 T122 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 26334 T122 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 26339 T96 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 26339 T96 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 26404 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 26418 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 26424 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 26428 T126 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37b11602 name:ZooKeeperConnection Watcher:127.0.0.1:51664/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 26429 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 26433 T96 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 26441 T96 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 26884 T96 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 26888 T96 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51683
[junit4:junit4] 2> 26889 T96 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 26890 T96 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 26890 T96 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372597737541
[junit4:junit4] 2> 26891 T96 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372597737541\solr.xml
[junit4:junit4] 2> 26891 T96 oasc.CoreContainer.<init> New CoreContainer 754804834
[junit4:junit4] 2> 26891 T96 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372597737541\'
[junit4:junit4] 2> 26892 T96 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372597737541\'
[junit4:junit4] 2> 27006 T96 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 27007 T96 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 27007 T96 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 27008 T96 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 27008 T96 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 27008 T96 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 27008 T96 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 27009 T96 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 27009 T96 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 27009 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 27019 T96 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 27020 T96 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51664/solr
[junit4:junit4] 2> 27020 T96 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 27022 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 27042 T137 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@29ceabdb name:ZooKeeperConnection Watcher:127.0.0.1:51664 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 27043 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 27048 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 27048 T98 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f95333c890005, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 27062 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 27068 T139 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5afcb4cc name:ZooKeeperConnection Watcher:127.0.0.1:51664/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 27068 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 27081 T96 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 27939 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 27943 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51671_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51671/n_"}
[junit4:junit4] 2> 27966 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 27967 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 27967 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 28165 T96 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51683_n_
[junit4:junit4] 2> 28168 T96 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51683_n_
[junit4:junit4] 2> 28178 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 28179 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 28185 T139 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 28186 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 28193 T126 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 28194 T119 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 28223 T140 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 28224 T140 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 28229 T140 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 29616 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 29620 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51683_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51683/n_"}
[junit4:junit4] 2> 29621 T120 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 29621 T120 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 29648 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 29649 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 29650 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 30388 T140 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 30388 T140 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372597737541\collection1
[junit4:junit4] 2> 30389 T140 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 30392 T140 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 30392 T140 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 30399 T140 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372597737541\collection1\'
[junit4:junit4] 2> 30403 T140 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372597737541/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 30406 T140 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372597737541/collection1/lib/README' to classloader
[junit4:junit4] 2> 30478 T140 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 30547 T140 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 30550 T140 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 30577 T140 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 31358 T140 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 31374 T140 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 31378 T140 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 31414 T140 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 31422 T140 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 31429 T140 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 31431 T140 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 31432 T140 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 31432 T140 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 31434 T140 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 31435 T140 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 31435 T140 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 31435 T140 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372597737541\collection1\, dataDir=.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty1\
[junit4:junit4] 2> 31435 T140 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4ffdd6db
[junit4:junit4] 2> 31436 T140 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty1\
[junit4:junit4] 2> 31436 T140 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty1\index/
[junit4:junit4] 2> 31437 T140 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 31437 T140 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty1\index
[junit4:junit4] 2> 31443 T140 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_1,generation=1}
[junit4:junit4] 2> 31443 T140 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 31447 T140 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 31459 T140 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 31462 T140 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 31463 T140 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 31464 T140 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 31464 T140 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 31464 T140 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 31466 T140 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 31466 T140 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 31475 T140 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 31484 T140 oass.SolrIndexSearcher.<init> Opening Searcher@5cccc9d8 main
[junit4:junit4] 2> 31485 T140 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 31486 T140 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 31493 T140 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 31494 T140 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51683/n_ collection:collection1 shard:shard1
[junit4:junit4] 2> 31494 T141 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5cccc9d8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 31496 T140 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 31519 T140 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4] 2> 31528 T140 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 31528 T140 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 31529 T140 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51683/n_/collection1/
[junit4:junit4] 2> 31529 T140 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 31529 T140 oasc.SyncStrategy.syncToMe http://127.0.0.1:51683/n_/collection1/ has no replicas
[junit4:junit4] 2> 31530 T140 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51683/n_/collection1/ shard1
[junit4:junit4] 2> 31530 T140 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 32805 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 32839 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 32839 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 32840 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 32861 T140 oasc.ZkController.register We are http://127.0.0.1:51683/n_/collection1/ and leader is http://127.0.0.1:51683/n_/collection1/
[junit4:junit4] 2> 32861 T140 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51683/n_
[junit4:junit4] 2> 32861 T140 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 32862 T140 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 32862 T140 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 32866 T140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 32869 T96 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 32869 T96 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 32870 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 33279 T96 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 33284 T96 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51692
[junit4:junit4] 2> 33285 T96 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 33286 T96 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 33286 T96 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372597743978
[junit4:junit4] 2> 33287 T96 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372597743978\solr.xml
[junit4:junit4] 2> 33288 T96 oasc.CoreContainer.<init> New CoreContainer 3359805
[junit4:junit4] 2> 33288 T96 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372597743978\'
[junit4:junit4] 2> 33288 T96 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372597743978\'
[junit4:junit4] 2> 33403 T96 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 33403 T96 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 33403 T96 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 33404 T96 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 33405 T96 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 33405 T96 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 33405 T96 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 33406 T96 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 33406 T96 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 33408 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 33419 T96 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 33419 T96 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51664/solr
[junit4:junit4] 2> 33419 T96 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 33421 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 33446 T153 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@78859fea name:ZooKeeperConnection Watcher:127.0.0.1:51664 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 33448 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 33458 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 33459 T98 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f95333c890007, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 33466 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 33469 T155 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@38fdc2b name:ZooKeeperConnection Watcher:127.0.0.1:51664/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 33470 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 33479 T96 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 34311 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 34313 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51683_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51683/n_"}
[junit4:junit4] 2> 34332 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 34332 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 34332 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 34333 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 34455 T96 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51692_n_
[junit4:junit4] 2> 34457 T96 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51692_n_
[junit4:junit4] 2> 34464 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 34466 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 34467 T155 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 34467 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 34468 T139 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 34469 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 34473 T119 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 34475 T126 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 34487 T156 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 34487 T156 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 34490 T156 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 35804 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 35808 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51692_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51692/n_"}
[junit4:junit4] 2> 35808 T120 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 35809 T120 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 35837 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 35839 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 35839 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 35838 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 36432 T156 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 36433 T156 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372597743978\collection1
[junit4:junit4] 2> 36436 T156 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 36439 T156 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 36439 T156 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 36442 T156 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372597743978\collection1\'
[junit4:junit4] 2> 36445 T156 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372597743978/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 36446 T156 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372597743978/collection1/lib/README' to classloader
[junit4:junit4] 2> 36502 T156 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 36565 T156 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 36567 T156 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 36590 T156 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 37252 T156 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 37275 T156 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 37281 T156 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 37327 T156 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 37333 T156 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 37339 T156 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 37342 T156 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 37342 T156 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 37343 T156 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 37344 T156 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 37344 T156 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 37344 T156 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 37345 T156 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372597743978\collection1\, dataDir=.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty2\
[junit4:junit4] 2> 37345 T156 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4ffdd6db
[junit4:junit4] 2> 37346 T156 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty2\
[junit4:junit4] 2> 37346 T156 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty2\index/
[junit4:junit4] 2> 37347 T156 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 37347 T156 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty2\index
[junit4:junit4] 2> 37351 T156 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1fcfbd1d lockFactory=org.apache.lucene.store.NativeFSLockFactory@31eb3d60),segFN=segments_1,generation=1}
[junit4:junit4] 2> 37353 T156 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 37357 T156 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 37357 T156 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 37358 T156 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 37359 T156 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 37360 T156 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 37361 T156 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 37361 T156 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 37361 T156 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 37361 T156 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 37374 T156 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 37380 T156 oass.SolrIndexSearcher.<init> Opening Searcher@54b053b1 main
[junit4:junit4] 2> 37382 T156 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 37382 T156 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 37388 T157 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@54b053b1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 37390 T156 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 37391 T156 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51692/n_ collection:collection1 shard:shard2
[junit4:junit4] 2> 37392 T156 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 37409 T156 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
[junit4:junit4] 2> 37415 T156 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 37415 T156 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 37415 T156 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51692/n_/collection1/
[junit4:junit4] 2> 37415 T156 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 37415 T156 oasc.SyncStrategy.syncToMe http://127.0.0.1:51692/n_/collection1/ has no replicas
[junit4:junit4] 2> 37415 T156 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51692/n_/collection1/ shard2
[junit4:junit4] 2> 37416 T156 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 38767 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 38808 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 38809 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 38810 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 38812 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 38865 T156 oasc.ZkController.register We are http://127.0.0.1:51692/n_/collection1/ and leader is http://127.0.0.1:51692/n_/collection1/
[junit4:junit4] 2> 38865 T156 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51692/n_
[junit4:junit4] 2> 38865 T156 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 38867 T156 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 38867 T156 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 38875 T156 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 38879 T96 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 38880 T96 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 38880 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 39283 T96 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 39287 T96 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51701
[junit4:junit4] 2> 39287 T96 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 39288 T96 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 39288 T96 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372597750001
[junit4:junit4] 2> 39288 T96 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372597750001\solr.xml
[junit4:junit4] 2> 39288 T96 oasc.CoreContainer.<init> New CoreContainer 279713461
[junit4:junit4] 2> 39289 T96 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372597750001\'
[junit4:junit4] 2> 39289 T96 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372597750001\'
[junit4:junit4] 2> 39398 T96 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 39399 T96 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 39399 T96 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 39399 T96 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 39400 T96 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 39400 T96 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 39401 T96 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 39401 T96 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 39401 T96 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 39402 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 39409 T96 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 39409 T96 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51664/solr
[junit4:junit4] 2> 39410 T96 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 39412 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 39428 T169 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@438dac25 name:ZooKeeperConnection Watcher:127.0.0.1:51664 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 39429 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 39432 T98 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f95333c890009, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 39432 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 39440 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 39443 T171 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@34d8e29 name:ZooKeeperConnection Watcher:127.0.0.1:51664/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 39443 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 39456 T96 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 40298 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 40302 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51692_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51692/n_"}
[junit4:junit4] 2> 40326 T171 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 40327 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 40327 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 40329 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 40330 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 40433 T96 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51701_n_
[junit4:junit4] 2> 40438 T96 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51701_n_
[junit4:junit4] 2> 40449 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 40450 T171 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 40450 T171 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 40451 T155 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 40451 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 40452 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 40454 T139 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 40455 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 40464 T119 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 40467 T126 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 40486 T172 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 40486 T172 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 40492 T172 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 41839 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 41842 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51701_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51701/n_"}
[junit4:junit4] 2> 41842 T120 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 41843 T120 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 41862 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 41863 T171 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 41863 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 41864 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 41864 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 42525 T172 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 42525 T172 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372597750001\collection1
[junit4:junit4] 2> 42525 T172 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 42528 T172 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 42529 T172 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 42535 T172 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372597750001\collection1\'
[junit4:junit4] 2> 42539 T172 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372597750001/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 42542 T172 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372597750001/collection1/lib/README' to classloader
[junit4:junit4] 2> 42606 T172 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 42689 T172 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 42691 T172 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 42709 T172 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 43357 T172 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 43414 T172 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 43419 T172 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 43462 T172 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 43468 T172 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 43474 T172 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 43479 T172 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 43480 T172 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 43480 T172 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 43493 T172 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 43493 T172 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 43494 T172 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 43494 T172 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372597750001\collection1\, dataDir=.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty3\
[junit4:junit4] 2> 43494 T172 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4ffdd6db
[junit4:junit4] 2> 43496 T172 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty3\
[junit4:junit4] 2> 43496 T172 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty3\index/
[junit4:junit4] 2> 43496 T172 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 43496 T172 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty3\index
[junit4:junit4] 2> 43501 T172 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45662c96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d3aca61),segFN=segments_1,generation=1}
[junit4:junit4] 2> 43501 T172 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 43509 T172 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 43509 T172 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 43510 T172 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 43511 T172 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 43511 T172 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 43511 T172 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 43511 T172 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 43513 T172 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 43513 T172 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 43524 T172 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 43531 T172 oass.SolrIndexSearcher.<init> Opening Searcher@5814ef1c main
[junit4:junit4] 2> 43533 T172 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 43533 T172 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 43543 T172 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 43544 T172 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51701/n_ collection:collection1 shard:shard1
[junit4:junit4] 2> 43545 T173 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5814ef1c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 43552 T172 oasc.ZkController.register We are http://127.0.0.1:51701/n_/collection1/ and leader is http://127.0.0.1:51683/n_/collection1/
[junit4:junit4] 2> 43552 T172 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51701/n_
[junit4:junit4] 2> 43552 T172 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 43553 T172 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C5 name=collection1 org.apache.solr.core.SolrCore@1d60e50b url=http://127.0.0.1:51701/n_/collection1 node=127.0.0.1:51701_n_ C5_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:51701_n_, base_url=http://127.0.0.1:51701/n_}
[junit4:junit4] 2> 43561 T174 C5 P51701 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 43562 T174 C5 P51701 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 43562 T174 C5 P51701 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 43657 T174 C5 P51701 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 43660 T172 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 43664 T174 C5 P51701 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 43767 T96 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 43768 T96 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 43768 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 44359 T96 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 44362 T96 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51711
[junit4:junit4] 2> 44363 T96 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 44363 T96 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 44363 T96 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372597754873
[junit4:junit4] 2> 44364 T96 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372597754873\solr.xml
[junit4:junit4] 2> 44364 T96 oasc.CoreContainer.<init> New CoreContainer 805438827
[junit4:junit4] 2> 44365 T96 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372597754873\'
[junit4:junit4] 2> 44365 T96 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372597754873\'
[junit4:junit4] 2> 44505 T96 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 44506 T96 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 44507 T96 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 44508 T96 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 44508 T96 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 44509 T96 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 44510 T96 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 44510 T96 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 44511 T96 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 44512 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 44551 T96 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 44553 T96 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51664/solr
[junit4:junit4] 2> 44553 T96 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 44555 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 44576 T188 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5ede2674 name:ZooKeeperConnection Watcher:127.0.0.1:51664 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 44577 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 44581 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 44583 T98 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f95333c89000b, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 44588 T96 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 44594 T190 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4a20e202 name:ZooKeeperConnection Watcher:127.0.0.1:51664/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 44595 T96 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 44606 T96 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 44628 T131 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 45093 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 45097 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51701_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51701/n_"}
[junit4:junit4] 2> 45119 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 45122 T171 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 45123 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 45124 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 45125 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 45126 T190 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 45682 T96 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51711_n_
[junit4:junit4] 2> 45688 T96 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51711_n_
[junit4:junit4] 2> 45696 T131 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 45697 T131 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node3&state=recovering&nodeName=127.0.0.1:51701_n_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1069
[junit4:junit4] 2> 45703 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 45707 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 45714 T190 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 45740 T190 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 45741 T171 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 45741 T171 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 45747 T139 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 45747 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 45753 T155 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 45753 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 45769 T126 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 45772 T119 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 45802 T191 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 45802 T191 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 45805 T191 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 46757 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 46763 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51711_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51711/n_"}
[junit4:junit4] 2> 46763 T120 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 46764 T120 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 46797 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 46798 T190 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 46799 T171 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 46798 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 46799 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 46799 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 46872 T191 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 46872 T191 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372597754873\collection1
[junit4:junit4] 2> 46872 T191 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 46874 T191 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 46874 T191 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 46878 T191 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372597754873\collection1\'
[junit4:junit4] 2> 46882 T191 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372597754873/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 46886 T191 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372597754873/collection1/lib/README' to classloader
[junit4:junit4] 2> 46984 T191 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 47055 T191 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 47059 T191 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 47075 T191 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 47779 T191 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 47792 T191 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 47797 T191 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 47836 T191 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 47842 T191 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 47849 T191 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 47851 T191 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 47852 T191 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 47852 T191 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 47854 T191 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 47854 T191 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 47855 T191 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 47855 T191 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372597754873\collection1\, dataDir=.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty4\
[junit4:junit4] 2> 47855 T191 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4ffdd6db
[junit4:junit4] 2> 47856 T191 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty4\
[junit4:junit4] 2> 47856 T191 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty4\index/
[junit4:junit4] 2> 47856 T191 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 47857 T191 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.BasicDistributedZkTest-1372597730230/jetty4\index
[junit4:junit4] 2> 47861 T191 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7cd47819 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28fc1399),segFN=segments_1,generation=1}
[junit4:junit4] 2> 47861 T191 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 47865 T191 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 47866 T191 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 47866 T191 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 47867 T191 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 47868 T191 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 47868 T191 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 47870 T191 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 47870 T191 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 47871 T191 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 47881 T191 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 47887 T191 oass.SolrIndexSearcher.<init> Opening Searcher@7a2c93ed main
[junit4:junit4] 2> 47889 T191 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 47889 T191 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 47895 T192 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7a2c93ed main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 47896 T191 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 47896 T191 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51711/n_ collection:collection1 shard:shard2
[junit4:junit4] 2> 47903 T191 oasc.ZkController.register We are http://127.0.0.1:51711/n_/collection1/ and leader is http://127.0.0.1:51692/n_/collection1/
[junit4:junit4] 2> 47903 T191 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51711/n_
[junit4:junit4] 2> 47903 T191 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 47903 T191 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C6 name=collection1 org.apache.solr.core.SolrCore@1c1bbe2d url=http://127.0.0.1:51711/n_/collection1 node=127.0.0.1:51711_n_ C6_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:51711_n_, base_url=http://127.0.0.1:51711/n_}
[junit4:junit4] 2> 47904 T193 C6 P51711 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 47905 T193 C6 P51711 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 47905 T193 C6 P51711 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 47906 T193 C6 P51711 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 47906 T191 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 47908 T193 C6 P51711 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 47910 T96 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 47910 T96 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 47911 T96 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 47924 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 47926 T150 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 47928 T96 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):330
[junit4:junit4] 2> 47929 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C7 name=collection1 org.apache.solr.core.SolrCore@1d60e50b url=http://127.0.0.1:51701/n_/collection1 node=127.0.0.1:51701_n_ C7_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:51701_n_, base_url=http://127.0.0.1:51701/n_}
[junit4:junit4] 2> 47944 T174 C7 P51701 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:51683/n_/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 47955 T174 C7 P51701 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 47972 T174 C7 P51701 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51701/n_ START replicas=[http://127.0.0.1:51683/n_/collection1/] nUpdates=100
[junit4:junit4] 2> 47980 T174 C7 P51701 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 47980 T174 C7 P51701 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 47980 T174 C7 P51701 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 47980 T174 C7 P51701 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 47981 T174 C7 P51701 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 47981 T174 C7 P51701 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:51683/n_/collection1/. core=collection1
[junit4:junit4] 2> 47981 T174 C7 P51701 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C8 name=collection1 org.apache.solr.core.SolrCore@7b58555c url=http://127.0.0.1:51683/n_/collection1 node=127.0.0.1:51683_n_ C8_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:51683_n_, base_url=http://127.0.0.1:51683/n_, leader=true}
[junit4:junit4] 2> 48025 T135 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=5
[junit4:junit4] 2> 48060 T130 C8 P51683 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 48065 T130 C8 P51683 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_1,generation=1}
[junit4:junit4] 2> 48067 T130 C8 P51683 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 48067 T130 C8 P51683 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 48068 T130 C8 P51683 oass.SolrIndexSearcher.<init> Opening Searcher@44edbc6d realtime
[junit4:junit4] 2> 48068 T130 C8 P51683 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 48068 T130 C8 P51683 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 48
[junit4:junit4] 2> 48122 T174 C7 P51701 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 48122 T174 C7 P51701 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 2> 48137 T174 C7 P51701 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 48178 T133 C8 P51683 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 48179 T133 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=40
[junit4:junit4] 2> 48180 T174 C7 P51701 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 48180 T174 C7 P51701 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 48181 T174 C7 P51701 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 48181 T174 C7 P51701 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 48192 T174 C7 P51701 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 48419 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 48420 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51711_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51711/n_"}
[junit4:junit4] 2> 48429 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51701_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51701/n_"}
[junit4:junit4] 2> 48440 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 48440 T171 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 48441 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 48441 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 48443 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 48443 T190 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 48994 T150 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 48994 T150 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node4&state=recovering&nodeName=127.0.0.1:51711_n_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1068
[junit4:junit4] 2> 48998 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 50070 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C6_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:51711_n_, base_url=http://127.0.0.1:51711/n_}
[junit4:junit4] 2> 51131 T193 C6 P51711 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:51692/n_/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 51132 T193 C6 P51711 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51711/n_ START replicas=[http://127.0.0.1:51692/n_/collection1/] nUpdates=100
[junit4:junit4] 2> 51134 T193 C6 P51711 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 51134 T193 C6 P51711 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 51135 T193 C6 P51711 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 51135 T193 C6 P51711 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 51135 T193 C6 P51711 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 51138 T193 C6 P51711 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:51692/n_/collection1/. core=collection1
[junit4:junit4] 2> 51138 T193 C6 P51711 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 51154 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C9 name=collection1 org.apache.solr.core.SolrCore@47e95534 url=http://127.0.0.1:51692/n_/collection1 node=127.0.0.1:51692_n_ C9_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:51692_n_, base_url=http://127.0.0.1:51692/n_, leader=true}
[junit4:junit4] 2> 51168 T150 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 51170 T149 C9 P51692 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 51175 T149 C9 P51692 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1fcfbd1d lockFactory=org.apache.lucene.store.NativeFSLockFactory@31eb3d60),segFN=segments_1,generation=1}
[junit4:junit4] 2> 51176 T149 C9 P51692 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 51176 T149 C9 P51692 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 51176 T149 C9 P51692 oass.SolrIndexSearcher.<init> Opening Searcher@558d946f realtime
[junit4:junit4] 2> 51177 T149 C9 P51692 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 51177 T149 C9 P51692 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 51179 T193 C6 P51711 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 51179 T193 C6 P51711 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 51182 T147 C9 P51692 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 51183 T147 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 51184 T193 C6 P51711 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 51184 T193 C6 P51711 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 51184 T193 C6 P51711 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 51184 T193 C6 P51711 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 51190 T193 C6 P51711 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 51670 T120 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 51673 T120 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51711_n_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51711/n_"}
[junit4:junit4] 2> 51694 T155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 51696 T171 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 51696 T139 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 51697 T119 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 51698 T126 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 51701 T190 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 52226 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52227 T96 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C10 name=collection1 org.apache.solr.core.SolrCore@29c356d3 url=http://127.0.0.1:51671/n_/collection1 node=127.0.0.1:51671_n_ C10_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:51671_n_, base_url=http://127.0.0.1:51671/n_, leader=true}
[junit4:junit4] 2> 52321 T114 C10 P51671 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30aefbe1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682ec68b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 52322 T114 C10 P51671 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 52324 T114 C10 P51671 oass.SolrIndexSearcher.<init> Opening Searcher@18c527cf realtime
[junit4:junit4] 2> 52325 T114 C10 P51671 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439273072372744192)} 0 30
[junit4:junit4] 2> C6_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:51711_n_, base_url=http://127.0.0.1:51711/n_}
[junit4:junit4] 2> 52363 T183 C6 P51711 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7cd47819 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28fc1399),segFN=segments_1,generation=1}
[junit4:junit4] 2> 52364 T183 C6 P51711 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 52365 T183 C6 P51711 oass.SolrIndexSearcher.<init> Opening Searcher@6dc71e86 realtime
[junit4:junit4] 2> 52366 T183 C6 P51711 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={update.distrib=FROMLEADER&_version_=-1439273072394764288&update.from=http://127.0.0.1:51692/n_/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439273072394764288)} 0 8
[junit4:junit4] 2> C7_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:51701_n_, base_url=http://127.0.0.1:51701/n_}
[junit4:junit4] 2> 52375 T166 C7 P51701 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45662c96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d3aca61),segFN=segments_1,generation=1}
[junit4:junit4] 2> 52375 T166 C7 P51701 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 52377 T166 C7 P51701 oass.SolrIndexSearcher.<init> Opening Searcher@5fd20f7e realtime
[junit4:junit4] 2> 52378 T166 C7 P51701 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={update.distrib=FROMLEADER&_version_=-1439273072413638656&update.from=http://127.0.0.1:51683/n_/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439273072413638656)} 0 8
[junit4:junit4] 2> 52379 T130 C8 P51683 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1439273072413638656)} 0 22
[junit4:junit4] 2> 52379 T150 C9 P51692 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439273072394764288)} 0 40
[junit4:junit4] 2> 52380 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52383 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52395 T132 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=0
[junit4:junit4] 2> 52399 T167 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=1
[junit4:junit4] 2> 52401 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52405 T149 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=1
[junit4:junit4] 2> 52409 T185 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=0
[junit4:junit4] 2> 52415 T115 C10 P51671 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 52435 T115 C10 P51671 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30aefbe1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682ec68b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30aefbe1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682ec68b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 52435 T115 C10 P51671 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 52455 T115 C10 P51671 oass.SolrIndexSearcher.<init> Opening Searcher@1d2d739d main
[junit4:junit4] 2> 52458 T115 C10 P51671 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 52458 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d2d739d main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c1)}
[junit4:junit4] 2> 52459 T115 C10 P51671 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439273072472358912)],commit=} 0 47
[junit4:junit4] 2> 52479 T162 C7 P51701 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={distrib.from=http://127.0.0.1:51683/n_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439273072524787712)]} 0 4
[junit4:junit4] 2> 52480 T133 C8 P51683 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:51683/n_/collection1/, StdNode: http://127.0.0.1:51701/n_/collection1/, StdNode: http://127.0.0.1:51692/n_/collection1/, StdNode: http://127.0.0.1:51711/n_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 52485 T163 C7 P51701 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 52485 T131 C8 P51683 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 52488 T148 C9 P51692 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 52488 T184 C6 P51711 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 52490 T184 C6 P51711 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 52488 T148 C9 P51692 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 52492 T184 C6 P51711 oass.SolrIndexSearcher.<init> Opening Searcher@51a688d main
[junit4:junit4] 2> 52492 T148 C9 P51692 oass.SolrIndexSearcher.<init> Opening Searcher@16364f main
[junit4:junit4] 2> 52500 T184 C6 P51711 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 52502 T148 C9 P51692 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 52502 T192 oasc.JmxMonitoredMap.put WARN Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:305)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1844)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1721)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 52503 T157 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16364f main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 52503 T192 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@51a688d main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 52504 T148 C9 P51692 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> 52505 T184 C6 P51711 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 17
[junit4:junit4] 2> 52508 T163 C7 P51701 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45662c96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d3aca61),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45662c96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d3aca61),segFN=segments_2,generation=2}
[junit4:junit4] 2> 52508 T163 C7 P51701 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 52510 T131 C8 P51683 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_2,generation=2}
[junit4:junit4] 2> 52510 T131 C8 P51683 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 52512 T163 C7 P51701 oass.SolrIndexSearcher.<init> Opening Searcher@3504b1cf main
[junit4:junit4] 2> 52512 T163 C7 P51701 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 52513 T131 C8 P51683 oass.SolrIndexSearcher.<init> Opening Searcher@46610747 main
[junit4:junit4] 2> 52513 T173 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3504b1cf main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c1)}
[junit4:junit4] 2> 52515 T163 C7 P51701 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 30
[junit4:junit4] 2> 52515 T141 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@46610747 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c1)}
[junit4:junit4] 2> 52515 T131 C8 P51683 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 52516 T131 C8 P51683 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 31
[junit4:junit4] 2> 52516 T133 C8 P51683 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439273072524787712)],commit=} 0 54
[junit4:junit4] 2> 52518 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52520 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52539 T135 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=15
[junit4:junit4] 2> 52543 T164 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 52551 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52556 T145 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 52560 T182 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 52562 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52565 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52624 T151 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763669&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=44
[junit4:junit4] 2> 52624 T165 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763669&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=28
[junit4:junit4] 2> 52648 T166 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763669&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=3
[junit4:junit4] 2> 52650 T130 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=80
[junit4:junit4] 2> 52661 T162 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763751&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 52661 T150 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763751&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 52666 T163 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763751&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=1
[junit4:junit4] 2> 52667 T167 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=15
[junit4:junit4] 2> 52668 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52682 T147 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763771&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 52682 T164 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763771&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 52686 T165 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763771&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=1
[junit4:junit4] 2> 52687 T149 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=15
[junit4:junit4] 2> 52706 T148 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763791&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 52706 T166 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763791&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 52711 T162 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597763791&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 52712 T180 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=20
[junit4:junit4] 2> 52720 T110 C10 P51671 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 52784 T110 C10 P51671 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30aefbe1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682ec68b),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30aefbe1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682ec68b),segFN=segments_3,generation=3}
[junit4:junit4] 2> 52784 T110 C10 P51671 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 52788 T110 C10 P51671 oass.SolrIndexSearcher.<init> Opening Searcher@2401c0b2 main
[junit4:junit4] 2> 52789 T110 C10 P51671 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 52790 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2401c0b2 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):c1)}
[junit4:junit4] 2> 52791 T110 C10 P51671 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439273072791126016)],commit=} 0 75
[junit4:junit4] 2> 52880 T163 C7 P51701 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={distrib.from=http://127.0.0.1:51683/n_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439273072880254976)]} 0 72
[junit4:junit4] 2> 52881 T132 C8 P51683 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={distrib.from=http://127.0.0.1:51692/n_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439273072880254976)]} 0 80
[junit4:junit4] 2> 52882 T145 C9 P51692 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:51683/n_/collection1/, StdNode: http://127.0.0.1:51701/n_/collection1/, StdNode: http://127.0.0.1:51692/n_/collection1/, StdNode: http://127.0.0.1:51711/n_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 52887 T164 C7 P51701 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 52889 T178 C6 P51711 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 52887 T131 C8 P51683 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 52893 T178 C6 P51711 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 52892 T151 C9 P51692 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 52894 T178 C6 P51711 oass.SolrIndexSearcher.<init> Opening Searcher@7d25da76 main
[junit4:junit4] 2> 52901 T178 C6 P51711 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 52901 T151 C9 P51692 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 52903 T151 C9 P51692 oass.SolrIndexSearcher.<init> Opening Searcher@7e306231 main
[junit4:junit4] 2> 52905 T151 C9 P51692 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 52903 T192 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7d25da76 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 52907 T178 C6 P51711 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 19
[junit4:junit4] 2> 52907 T157 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7e306231 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 52908 T151 C9 P51692 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> 52925 T131 C8 P51683 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_3,generation=3}
[junit4:junit4] 2> 52926 T131 C8 P51683 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 52929 T164 C7 P51701 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45662c96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d3aca61),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45662c96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d3aca61),segFN=segments_3,generation=3}
[junit4:junit4] 2> 52929 T164 C7 P51701 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 52932 T131 C8 P51683 oass.SolrIndexSearcher.<init> Opening Searcher@1b8cf995 main
[junit4:junit4] 2> 52932 T164 C7 P51701 oass.SolrIndexSearcher.<init> Opening Searcher@cc938b8 main
[junit4:junit4] 2> 52933 T141 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b8cf995 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):c1)}
[junit4:junit4] 2> 52934 T131 C8 P51683 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 52935 T164 C7 P51701 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 52936 T131 C8 P51683 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 49
[junit4:junit4] 2> 52935 T173 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@cc938b8 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):c1)}
[junit4:junit4] 2> 52939 T164 C7 P51701 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 53
[junit4:junit4] 2> 52940 T145 C9 P51692 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 146
[junit4:junit4] 2> 52941 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52943 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52948 T133 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 52954 T165 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 52955 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52961 T147 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=2
[junit4:junit4] 2> 52965 T185 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 52967 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52970 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52981 T181 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764073&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 52982 T166 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764073&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 52989 T162 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764073&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=1
[junit4:junit4] 2> 52992 T135 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=18
[junit4:junit4] 2> 53003 T163 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764096&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=2
[junit4:junit4] 2> 53004 T184 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764096&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 53011 T164 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764096&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=1
[junit4:junit4] 2> 53014 T167 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=17
[junit4:junit4] 2> 53018 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53031 T182 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764124&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 53035 T165 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764124&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 53045 T166 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764124&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=1
[junit4:junit4] 2> 53048 T149 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=22
[junit4:junit4] 2> 53057 T183 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764151&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 53061 T162 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764151&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 53065 T163 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764151&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 53067 T180 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=15
[junit4:junit4] 2> 53077 T112 C10 P51671 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53084 T112 C10 P51671 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30aefbe1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682ec68b),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30aefbe1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682ec68b),segFN=segments_4,generation=4}
[junit4:junit4] 2> 53084 T112 C10 P51671 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 53086 T112 C10 P51671 oass.SolrIndexSearcher.<init> Opening Searcher@50157fd8 main
[junit4:junit4] 2> 53087 T112 C10 P51671 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53089 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@50157fd8 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):c1)}
[junit4:junit4] 2> 53090 T112 C10 P51671 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439273073165467648)],commit=} 0 16
[junit4:junit4] 2> 53111 T167 C7 P51701 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={distrib.from=http://127.0.0.1:51683/n_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439273073192730624)]} 0 5
[junit4:junit4] 2> 53113 T130 C8 P51683 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={distrib.from=http://127.0.0.1:51701/n_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439273073192730624)]} 0 13
[junit4:junit4] 2> 53114 T164 C7 P51701 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:51683/n_/collection1/, StdNode: http://127.0.0.1:51701/n_/collection1/, StdNode: http://127.0.0.1:51692/n_/collection1/, StdNode: http://127.0.0.1:51711/n_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 53130 T148 C9 P51692 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53131 T148 C9 P51692 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 53131 T148 C9 P51692 oass.SolrIndexSearcher.<init> Opening Searcher@267ae84 main
[junit4:junit4] 2> 53132 T148 C9 P51692 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53134 T132 C8 P51683 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53152 T132 C8 P51683 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_4,generation=4}
[junit4:junit4] 2> 53153 T132 C8 P51683 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 53156 T132 C8 P51683 oass.SolrIndexSearcher.<init> Opening Searcher@264774b1 main
[junit4:junit4] 2> 53159 T132 C8 P51683 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53182 T178 C6 P51711 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53183 T178 C6 P51711 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 53183 T178 C6 P51711 oass.SolrIndexSearcher.<init> Opening Searcher@705181d8 main
[junit4:junit4] 2> 53183 T178 C6 P51711 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53184 T192 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@705181d8 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 53185 T178 C6 P51711 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 2> 53192 T165 C7 P51701 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53197 T165 C7 P51701 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45662c96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d3aca61),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45662c96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d3aca61),segFN=segments_4,generation=4}
[junit4:junit4] 2> 53198 T165 C7 P51701 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 53200 T165 C7 P51701 oass.SolrIndexSearcher.<init> Opening Searcher@4346d2cd main
[junit4:junit4] 2> 53203 T165 C7 P51701 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53203 T173 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4346d2cd main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):c1)}
[junit4:junit4] 2> 53204 T141 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@264774b1 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):c1)}
[junit4:junit4] 2> 53205 T165 C7 P51701 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> 53206 T157 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@267ae84 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 53207 T132 C8 P51683 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 73
[junit4:junit4] 2> 53207 T148 C9 P51692 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 77
[junit4:junit4] 2> 53209 T164 C7 P51701 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 117
[junit4:junit4] 2> 53211 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53212 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53217 T134 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 53221 T162 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 53222 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53227 T150 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 53230 T185 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 53232 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53235 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53244 T133 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764338&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 53250 T181 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764338&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 53257 T135 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764338&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 53259 T131 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=20
[junit4:junit4] 2> 53277 T184 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764371&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 53280 T130 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764371&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=2
[junit4:junit4] 2> 53286 T132 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764371&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=1
[junit4:junit4] 2> 53287 T163 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=15
[junit4:junit4] 2> 53288 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53296 T182 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764391&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 53299 T133 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764391&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 53309 T135 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764391&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 53311 T151 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=19
[junit4:junit4] 2> 53319 T178 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764414&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 53319 T131 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764414&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 53323 T130 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764414&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=1
[junit4:junit4] 2> 53324 T180 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=9
[junit4:junit4] 2> 53331 T113 C10 P51671 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53338 T113 C10 P51671 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30aefbe1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682ec68b),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@30aefbe1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682ec68b),segFN=segments_5,generation=5}
[junit4:junit4] 2> 53338 T113 C10 P51671 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 53342 T113 C10 P51671 oass.SolrIndexSearcher.<init> Opening Searcher@270568f main
[junit4:junit4] 2> 53343 T113 C10 P51671 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53344 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@270568f main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):c1)}
[junit4:junit4] 2> 53345 T113 C10 P51671 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439273073431805952)],commit=} 0 17
[junit4:junit4] 2> 53364 T167 C7 P51701 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={distrib.from=http://127.0.0.1:51683/n_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439273073456971776)]} 0 4
[junit4:junit4] 2> 53366 T132 C8 P51683 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={distrib.from=http://127.0.0.1:51711/n_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439273073456971776)]} 0 14
[junit4:junit4] 2> 53367 T185 C6 P51711 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:51683/n_/collection1/, StdNode: http://127.0.0.1:51701/n_/collection1/, StdNode: http://127.0.0.1:51692/n_/collection1/, StdNode: http://127.0.0.1:51711/n_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 53372 T134 C8 P51683 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53373 T147 C9 P51692 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53375 T147 C9 P51692 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 53376 T181 C6 P51711 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53377 T181 C6 P51711 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 53377 T181 C6 P51711 oass.SolrIndexSearcher.<init> Opening Searcher@2bfcfc7c main
[junit4:junit4] 2> 53379 T181 C6 P51711 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53372 T165 C7 P51701 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53379 T147 C9 P51692 oass.SolrIndexSearcher.<init> Opening Searcher@fcf0783 main
[junit4:junit4] 2> 53379 T192 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2bfcfc7c main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 53380 T147 C9 P51692 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53382 T157 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@fcf0783 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 53384 T147 C9 P51692 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> 53385 T181 C6 P51711 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 53388 T165 C7 P51701 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45662c96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d3aca61),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45662c96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d3aca61),segFN=segments_5,generation=5}
[junit4:junit4] 2> 53388 T165 C7 P51701 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 53391 T165 C7 P51701 oass.SolrIndexSearcher.<init> Opening Searcher@b1e6d04 main
[junit4:junit4] 2> 53393 T173 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b1e6d04 main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):c1)}
[junit4:junit4] 2> 53397 T165 C7 P51701 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53397 T165 C7 P51701 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 25
[junit4:junit4] 2> 53400 T134 C8 P51683 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40dcf583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41e7ebab),segFN=segments_5,generation=5}
[junit4:junit4] 2> 53400 T134 C8 P51683 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 53403 T134 C8 P51683 oass.SolrIndexSearcher.<init> Opening Searcher@51e7c3f6 main
[junit4:junit4] 2> 53405 T134 C8 P51683 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53405 T141 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@51e7c3f6 main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):c1)}
[junit4:junit4] 2> 53406 T134 C8 P51683 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 35
[junit4:junit4] 2> 53407 T185 C6 P51711 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_ path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 58
[junit4:junit4] 2> 53408 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53410 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53414 T133 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 53418 T164 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 53421 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53426 T149 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 53430 T184 C6 P51711 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 53433 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53436 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53446 T148 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764539&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 53447 T166 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764539&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 53462 T162 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764539&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 53464 T135 C8 P51683 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=24
[junit4:junit4] 2> 53470 T150 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764565&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 53472 T167 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764565&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 53476 T165 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764565&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=1
[junit4:junit4] 2> 53477 T163 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=11
[junit4:junit4] 2> 53479 T96 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53487 T164 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764584&shard.url=127.0.0.1:51683/n_/collection1/|127.0.0.1:51701/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 53490 T151 C9 P51692 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372597764584&shard.url=127.0.0.1:51692/n_/collection1/|127.0.0.1:51711/n_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 53500 T166 C7 P51701 oasc.SolrCore.execute [collection1] webapp=/n_ path=/select params={NOW=1372
[...truncated too long message...]
7)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {foo_b=Pulsing41(freqCutoff=4 minBlockSize=58 maxBlockSize=150), n_f1=PostingsFormat(name=MockSep), cat=MockVariableIntBlock(baseBlockSize=51), foo_d=PostingsFormat(name=NestedPulsing), n_tl1=PostingsFormat(name=MockSep), foo_f=Pulsing41(freqCutoff=4 minBlockSize=58 maxBlockSize=150), n_d1=MockVariableIntBlock(baseBlockSize=51), rnd_b=PostingsFormat(name=NestedPulsing), intDefault=MockVariableIntBlock(baseBlockSize=51), n_td1=PostingsFormat(name=MockSep), timestamp=MockVariableIntBlock(baseBlockSize=51), id=PostingsFormat(name=NestedPulsing), range_facet_sl=Pulsing41(freqCutoff=4 minBlockSize=58 maxBlockSize=150), range_facet_si=PostingsFormat(name=MockSep), oddField_s=Pulsing41(freqCutoff=4 minBlockSize=58 maxBlockSize=150), sequence_i=Pulsing41(freqCutoff=4 minBlockSize=58 maxBlockSize=150), name=PostingsFormat(name=NestedPulsing), foo_i=PostingsFormat(name=MockSep), regex_dup_B_s=MockVariableIntBlock(baseBlockSize=51), multiDefault=PostingsFormat(name=MockSep), n_tf1=MockVariableIntBlock(baseBlockSize=51), n_dt1=PostingsFormat(name=MockSep), genre_s=Pulsing41(freqCutoff=4 minBlockSize=58 maxBlockSize=150), author_t=PostingsFormat(name=MockSep), range_facet_l=MockVariableIntBlock(baseBlockSize=51), n_ti1=PostingsFormat(name=NestedPulsing), text=Pulsing41(freqCutoff=4 minBlockSize=58 maxBlockSize=150), _version_=MockVariableIntBlock(baseBlockSize=51), val_i=PostingsFormat(name=NestedPulsing), SubjectTerms_mfacet=MockVariableIntBlock(baseBlockSize=51), series_t=PostingsFormat(name=MockSep), a_t=MockVariableIntBlock(baseBlockSize=51), n_tdt1=MockVariableIntBlock(baseBlockSize=51), regex_dup_A_s=Pulsing41(freqCutoff=4 minBlockSize=58 maxBlockSize=150), price=Pulsing41(freqCutoff=4 minBlockSize=58 maxBlockSize=150), other_tl1=MockVariableIntBlock(baseBlockSize=51), n_l1=MockVariableIntBlock(baseBlockSize=51), a_si=PostingsFormat(name=MockSep), inStock=Pulsing41(freqCutoff=4 minBlockSize=58 maxBlockSize=150)}, docValues:{timestamp=DocValuesFormat(name=Asserting)}, sim=DefaultSimilarity, locale=ro, timezone=Chile/Continental
[junit4:junit4] 2> NOTE: Windows 7 6.1 amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=2,free=185066800,total=252837888
[junit4:junit4] 2> NOTE: All tests run in this JVM: [FileUtilsTest, TestFastLRUCache, HdfsUnloadDistributedZkTest, XsltUpdateRequestHandlerTest, TestLazyCores, BasicDistributedZkTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=BasicDistributedZkTest -Dtests.seed=53111398A2E0B953 -Dtests.slow=true -Dtests.locale=ro -Dtests.timezone=Chile/Continental -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR 0.00s | BasicDistributedZkTest (suite) <<<
[junit4:junit4] > Throwable #1: com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.BasicDistributedZkTest:
[junit4:junit4] > 1) Thread[id=438, name=recoveryCmdExecutor-179-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
[junit4:junit4] > at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method)
[junit4:junit4] > at java.net.DualStackPlainSocketImpl.socketConnect(DualStackPlainSocketImpl.java:85)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
[junit4:junit4] > at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:172)
[junit4:junit4] > at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
[junit4:junit4] > at java.net.Socket.connect(Socket.java:579)
[junit4:junit4] > at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
[junit4:junit4] > at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
[junit4:junit4] > at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
[junit4:junit4] > at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
[junit4:junit4] > at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([53111398A2E0B953]:0)Throwable #2: com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
[junit4:junit4] > 1) Thread[id=438, name=recoveryCmdExecutor-179-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
[junit4:junit4] > at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method)
[junit4:junit4] > at java.net.DualStackPlainSocketImpl.socketConnect(DualStackPlainSocketImpl.java:85)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
[junit4:junit4] > at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:172)
[junit4:junit4] > at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
[junit4:junit4] > at java.net.Socket.connect(Socket.java:579)
[junit4:junit4] > at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
[junit4:junit4] > at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
[junit4:junit4] > at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
[junit4:junit4] > at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
[junit4:junit4] > at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([53111398A2E0B953]:0)
[junit4:junit4] Completed in 245.38s, 1 test, 2 errors <<< FAILURES!
[...truncated 927 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:386: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:366: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build.xml:190: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\common-build.xml:443: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:1245: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:889: There were test failures: 312 suites, 1316 tests, 2 suite-level errors, 1215 ignored
Total time: 24 minutes 23 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_25 -XX:+UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure