lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Mark Miller <markrmil...@gmail.com>
Subject Re: [JENKINS] Lucene-Solr-Tests-trunk-Java7 - Build # 4102 - Still Failing
Date Mon, 01 Jul 2013 13:39:54 GMT
FreeBSD issue it looks - that just started recently - an http connect attempt that won't time out even though there is a timeout set. I need to try and dig into it on my FreeBSD machine when I get a chance.

- Mark

On Jul 1, 2013, at 9:16 AM, Apache Jenkins Server <jenkins@builds.apache.org> wrote:

> Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java7/4102/
> 
> 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=2538, name=recoveryCmdExecutor-1003-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]         at java.net.PlainSocketImpl.socketConnect(Native Method)         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.SocksSocketImpl.connect(SocksSocketImpl.java:391)         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:722)
> 
> Stack Trace:
> com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.BasicDistributedZkTest: 
>   1) Thread[id=2538, name=recoveryCmdExecutor-1003-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
>        at java.net.PlainSocketImpl.socketConnect(Native Method)
>        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.SocksSocketImpl.connect(SocksSocketImpl.java:391)
>        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:722)
> 	at __randomizedtesting.SeedInfo.seed([61B7523138BE4F06]: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=2538, name=recoveryCmdExecutor-1003-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]         at java.net.PlainSocketImpl.socketConnect(Native Method)         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.SocksSocketImpl.connect(SocksSocketImpl.java:391)         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:722)
> 
> Stack Trace:
> com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
>   1) Thread[id=2538, name=recoveryCmdExecutor-1003-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
>        at java.net.PlainSocketImpl.socketConnect(Native Method)
>        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.SocksSocketImpl.connect(SocksSocketImpl.java:391)
>        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:722)
> 	at __randomizedtesting.SeedInfo.seed([61B7523138BE4F06]:0)
> 
> 
> 
> 
> Build Log:
> [...truncated 9599 lines...]
> [junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest
> [junit4:junit4]   2> 732978 T2067 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /zm/x
> [junit4:junit4]   2> 732981 T2067 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
> [junit4:junit4]   2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZkTest-1372684133825
> [junit4:junit4]   2> 732983 T2067 oasc.ZkTestServer.run STARTING ZK TEST SERVER
> [junit4:junit4]   2> 732983 T2068 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
> [junit4:junit4]   2> 733084 T2067 oasc.ZkTestServer.run start zk server on port:17602
> [junit4:junit4]   2> 733085 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 733090 T2074 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3329a45 name:ZooKeeperConnection Watcher:127.0.0.1:17602 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 733090 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 733091 T2067 oascc.SolrZkClient.makePath makePath: /solr
> [junit4:junit4]   2> 733108 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 733110 T2076 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4792a0c9 name:ZooKeeperConnection Watcher:127.0.0.1:17602/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 733110 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 733111 T2067 oascc.SolrZkClient.makePath makePath: /collections/collection1
> [junit4:junit4]   2> 733115 T2067 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
> [junit4:junit4]   2> 733118 T2067 oascc.SolrZkClient.makePath makePath: /collections/control_collection
> [junit4:junit4]   2> 733121 T2067 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
> [junit4:junit4]   2> 733125 T2067 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
> [junit4:junit4]   2> 733125 T2067 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
> [junit4:junit4]   2> 733131 T2067 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
> [junit4:junit4]   2> 733132 T2067 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
> [junit4:junit4]   2> 733240 T2067 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
> [junit4:junit4]   2> 733240 T2067 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
> [junit4:junit4]   2> 733245 T2067 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
> [junit4:junit4]   2> 733246 T2067 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
> [junit4:junit4]   2> 733249 T2067 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
> [junit4:junit4]   2> 733250 T2067 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
> [junit4:junit4]   2> 733257 T2067 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
> [junit4:junit4]   2> 733258 T2067 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
> [junit4:junit4]   2> 733261 T2067 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
> [junit4:junit4]   2> 733262 T2067 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
> [junit4:junit4]   2> 733265 T2067 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
> [junit4:junit4]   2> 733265 T2067 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
> [junit4:junit4]   2> 733273 T2067 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
> [junit4:junit4]   2> 733273 T2067 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
> [junit4:junit4]   2> 733458 T2067 oejs.Server.doStart jetty-8.1.10.v20130312
> [junit4:junit4]   2> 733461 T2067 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:19896
> [junit4:junit4]   2> 733462 T2067 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
> [junit4:junit4]   2> 733462 T2067 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
> [junit4:junit4]   2> 733462 T2067 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372684134121
> [junit4:junit4]   2> 733463 T2067 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372684134121/solr.xml
> [junit4:junit4]   2> 733463 T2067 oasc.CoreContainer.<init> New CoreContainer 1845363899
> [junit4:junit4]   2> 733463 T2067 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372684134121/'
> [junit4:junit4]   2> 733464 T2067 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372684134121/'
> [junit4:junit4]   2> 733550 T2067 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
> [junit4:junit4]   2> 733550 T2067 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
> [junit4:junit4]   2> 733551 T2067 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
> [junit4:junit4]   2> 733551 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
> [junit4:junit4]   2> 733551 T2067 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
> [junit4:junit4]   2> 733552 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
> [junit4:junit4]   2> 733552 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
> [junit4:junit4]   2> 733552 T2067 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
> [junit4:junit4]   2> 733553 T2067 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
> [junit4:junit4]   2> 733553 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
> [junit4:junit4]   2> 733564 T2067 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
> [junit4:junit4]   2> 733565 T2067 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:17602/solr
> [junit4:junit4]   2> 733565 T2067 oasc.ZkController.checkChrootPath zkHost includes chroot
> [junit4:junit4]   2> 733566 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 733569 T2087 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5766e024 name:ZooKeeperConnection Watcher:127.0.0.1:17602 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 733569 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 733584 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
> [junit4:junit4]   2> 733597 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 733599 T2089 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6974bbb6 name:ZooKeeperConnection Watcher:127.0.0.1:17602/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 733599 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 733602 T2067 oascc.SolrZkClient.makePath makePath: /overseer/queue
> [junit4:junit4]   2> 733611 T2067 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
> [junit4:junit4]   2> 733614 T2067 oascc.SolrZkClient.makePath makePath: /live_nodes
> [junit4:junit4]   2> 733621 T2067 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:19896_zm%2Fx
> [junit4:junit4]   2> 733623 T2067 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:19896_zm%2Fx
> [junit4:junit4]   2> 733627 T2067 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
> [junit4:junit4]   2> 733642 T2067 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
> [junit4:junit4]   2> 733646 T2067 oasc.Overseer.start Overseer (id=89960227394879491-127.0.0.1:19896_zm%2Fx-n_0000000000) starting
> [junit4:junit4]   2> 733656 T2067 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
> [junit4:junit4]   2> 733667 T2091 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
> [junit4:junit4]   2> 733667 T2067 oascc.SolrZkClient.makePath makePath: /clusterstate.json
> [junit4:junit4]   2> 733670 T2067 oascc.SolrZkClient.makePath makePath: /aliases.json
> [junit4:junit4]   2> 733677 T2067 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
> [junit4:junit4]   2> 733680 T2090 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
> [junit4:junit4]   2> 733684 T2092 oasc.ZkController.publish publishing core=collection1 state=down
> [junit4:junit4]   2> 733684 T2092 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 733685 T2092 oasc.ZkController.waitForCoreNodeName look for our core node name
> [junit4:junit4]   2> 735184 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 735184 T2090 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:19896_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:19896/zm/x"}
> [junit4:junit4]   2> 735185 T2090 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
> [junit4:junit4]   2> 735185 T2090 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
> [junit4:junit4]   2> 735201 T2089 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> 735688 T2092 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
> [junit4:junit4]   2> 735688 T2092 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372684134121/collection1
> [junit4:junit4]   2> 735689 T2092 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
> [junit4:junit4]   2> 735690 T2092 oasc.ZkController.createCollectionZkNode Collection zkNode exists
> [junit4:junit4]   2> 735690 T2092 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
> [junit4:junit4]   2> 735692 T2092 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372684134121/collection1/'
> [junit4:junit4]   2> 735693 T2092 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372684134121/collection1/lib/README' to classloader
> [junit4:junit4]   2> 735694 T2092 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372684134121/collection1/lib/classes/' to classloader
> [junit4:junit4]   2> 735746 T2092 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
> [junit4:junit4]   2> 735808 T2092 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
> [junit4:junit4]   2> 735911 T2092 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
> [junit4:junit4]   2> 735918 T2092 oass.IndexSchema.readSchema [collection1] Schema name=test
> [junit4:junit4]   2> 736551 T2092 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
> [junit4:junit4]   2> 736564 T2092 oass.IndexSchema.readSchema default search field in schema is text
> [junit4:junit4]   2> 736568 T2092 oass.IndexSchema.readSchema unique key field: id
> [junit4:junit4]   2> 736585 T2092 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
> [junit4:junit4]   2> 736590 T2092 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
> [junit4:junit4]   2> 736595 T2092 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
> [junit4:junit4]   2> 736596 T2092 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
> [junit4:junit4]   2> 736596 T2092 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
> [junit4:junit4]   2> 736596 T2092 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
> [junit4:junit4]   2> 736597 T2092 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
> [junit4:junit4]   2> 736598 T2092 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
> [junit4:junit4]   2> 736598 T2092 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
> [junit4:junit4]   2> 736598 T2092 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372684134121/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/control/data/
> [junit4:junit4]   2> 736599 T2092 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@798e662b
> [junit4:junit4]   2> 736600 T2092 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/control/data
> [junit4:junit4]   2> 736600 T2092 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/control/data/index/
> [junit4:junit4]   2> 736600 T2092 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/control/data/index' doesn't exist. Creating new index...
> [junit4:junit4]   2> 736601 T2092 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/control/data/index
> [junit4:junit4]   2> 736605 T2092 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@47d81405 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79787b31),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 736606 T2092 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
> [junit4:junit4]   2> 736608 T2092 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
> [junit4:junit4]   2> 736609 T2092 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
> [junit4:junit4]   2> 736609 T2092 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
> [junit4:junit4]   2> 736610 T2092 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
> [junit4:junit4]   2> 736610 T2092 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
> [junit4:junit4]   2> 736611 T2092 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
> [junit4:junit4]   2> 736611 T2092 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
> [junit4:junit4]   2> 736612 T2092 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
> [junit4:junit4]   2> 736612 T2092 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
> [junit4:junit4]   2> 736628 T2092 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
> [junit4:junit4]   2> 736636 T2092 oass.SolrIndexSearcher.<init> Opening Searcher@782f5cc2 main
> [junit4:junit4]   2> 736637 T2092 oasu.CommitTracker.<init> Hard AutoCommit: disabled
> [junit4:junit4]   2> 736637 T2092 oasu.CommitTracker.<init> Soft AutoCommit: disabled
> [junit4:junit4]   2> 736641 T2093 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@782f5cc2 main{StandardDirectoryReader(segments_1:1)}
> [junit4:junit4]   2> 736642 T2092 oasc.CoreContainer.registerCore registering core: collection1
> [junit4:junit4]   2> 736643 T2092 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:19896/zm/x collection:control_collection shard:shard1
> [junit4:junit4]   2> 736643 T2092 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
> [junit4:junit4]   2> 736662 T2092 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
> [junit4:junit4]   2> 736665 T2092 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
> [junit4:junit4]   2> 736665 T2092 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
> [junit4:junit4]   2> 736665 T2092 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:19896/zm/x/collection1/
> [junit4:junit4]   2> 736666 T2092 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
> [junit4:junit4]   2> 736666 T2092 oasc.SyncStrategy.syncToMe http://127.0.0.1:19896/zm/x/collection1/ has no replicas
> [junit4:junit4]   2> 736666 T2092 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:19896/zm/x/collection1/ shard1
> [junit4:junit4]   2> 736667 T2092 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
> [junit4:junit4]   2> 736707 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 736715 T2089 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> 736724 T2092 oasc.ZkController.register We are http://127.0.0.1:19896/zm/x/collection1/ and leader is http://127.0.0.1:19896/zm/x/collection1/
> [junit4:junit4]   2> 736724 T2092 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:19896/zm/x
> [junit4:junit4]   2> 736724 T2092 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
> [junit4:junit4]   2> 736724 T2092 oasc.ZkController.publish publishing core=collection1 state=active
> [junit4:junit4]   2> 736725 T2092 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 736726 T2092 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 736728 T2067 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
> [junit4:junit4]   2> 736728 T2067 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
> [junit4:junit4]   2> 736729 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
> [junit4:junit4]   2> 736746 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:
> [junit4:junit4]   2> 736748 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 736750 T2096 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@78c4fabc name:ZooKeeperConnection Watcher:127.0.0.1:17602/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 736750 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 736752 T2067 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
> [junit4:junit4]   2> 736755 T2067 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
> [junit4:junit4]   2> 737034 T2067 oejs.Server.doStart jetty-8.1.10.v20130312
> [junit4:junit4]   2> 737037 T2067 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:16933
> [junit4:junit4]   2> 737038 T2067 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
> [junit4:junit4]   2> 737039 T2067 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
> [junit4:junit4]   2> 737039 T2067 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372684137598
> [junit4:junit4]   2> 737040 T2067 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372684137598/solr.xml
> [junit4:junit4]   2> 737040 T2067 oasc.CoreContainer.<init> New CoreContainer 1071384450
> [junit4:junit4]   2> 737041 T2067 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372684137598/'
> [junit4:junit4]   2> 737041 T2067 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372684137598/'
> [junit4:junit4]   2> 737171 T2067 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
> [junit4:junit4]   2> 737172 T2067 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
> [junit4:junit4]   2> 737172 T2067 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
> [junit4:junit4]   2> 737173 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
> [junit4:junit4]   2> 737173 T2067 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
> [junit4:junit4]   2> 737174 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
> [junit4:junit4]   2> 737174 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
> [junit4:junit4]   2> 737175 T2067 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
> [junit4:junit4]   2> 737175 T2067 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
> [junit4:junit4]   2> 737176 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
> [junit4:junit4]   2> 737193 T2067 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
> [junit4:junit4]   2> 737194 T2067 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:17602/solr
> [junit4:junit4]   2> 737194 T2067 oasc.ZkController.checkChrootPath zkHost includes chroot
> [junit4:junit4]   2> 737195 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 737198 T2107 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14fa8922 name:ZooKeeperConnection Watcher:127.0.0.1:17602 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 737199 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 737214 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
> [junit4:junit4]   2> 737227 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 737229 T2109 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@66491c84 name:ZooKeeperConnection Watcher:127.0.0.1:17602/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 737229 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 737241 T2067 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
> [junit4:junit4]   2> 738222 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 738223 T2090 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:19896_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:19896/zm/x"}
> [junit4:junit4]   2> 738245 T2096 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> 738245 T2109 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> 738245 T2089 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> 738247 T2067 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:16933_zm%2Fx
> [junit4:junit4]   2> 738256 T2067 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:16933_zm%2Fx
> [junit4:junit4]   2> 738260 T2109 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> 738260 T2089 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> 738260 T2096 oascc.ZkStateReader$3.process Updating live nodes... (2)
> [junit4:junit4]   2> 738261 T2096 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> 738262 T2109 oascc.ZkStateReader$3.process Updating live nodes... (2)
> [junit4:junit4]   2> 738262 T2089 oascc.ZkStateReader$3.process Updating live nodes... (2)
> [junit4:junit4]   2> 738269 T2110 oasc.ZkController.publish publishing core=collection1 state=down
> [junit4:junit4]   2> 738269 T2110 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 738273 T2110 oasc.ZkController.waitForCoreNodeName look for our core node name
> [junit4:junit4]   2> 739760 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 739761 T2090 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:16933_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:16933/zm/x"}
> [junit4:junit4]   2> 739761 T2090 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
> [junit4:junit4]   2> 739761 T2090 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
> [junit4:junit4]   2> 739781 T2089 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> 739781 T2109 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> 739781 T2096 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> 740276 T2110 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
> [junit4:junit4]   2> 740276 T2110 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372684137598/collection1
> [junit4:junit4]   2> 740276 T2110 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
> [junit4:junit4]   2> 740277 T2110 oasc.ZkController.createCollectionZkNode Collection zkNode exists
> [junit4:junit4]   2> 740277 T2110 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
> [junit4:junit4]   2> 740279 T2110 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372684137598/collection1/'
> [junit4:junit4]   2> 740280 T2110 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372684137598/collection1/lib/README' to classloader
> [junit4:junit4]   2> 740281 T2110 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372684137598/collection1/lib/classes/' to classloader
> [junit4:junit4]   2> 740333 T2110 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
> [junit4:junit4]   2> 740395 T2110 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
> [junit4:junit4]   2> 740497 T2110 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
> [junit4:junit4]   2> 740504 T2110 oass.IndexSchema.readSchema [collection1] Schema name=test
> [junit4:junit4]   2> 741168 T2110 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
> [junit4:junit4]   2> 741181 T2110 oass.IndexSchema.readSchema default search field in schema is text
> [junit4:junit4]   2> 741185 T2110 oass.IndexSchema.readSchema unique key field: id
> [junit4:junit4]   2> 741202 T2110 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
> [junit4:junit4]   2> 741207 T2110 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
> [junit4:junit4]   2> 741211 T2110 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
> [junit4:junit4]   2> 741213 T2110 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
> [junit4:junit4]   2> 741213 T2110 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
> [junit4:junit4]   2> 741214 T2110 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
> [junit4:junit4]   2> 741215 T2110 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
> [junit4:junit4]   2> 741215 T2110 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
> [junit4:junit4]   2> 741215 T2110 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
> [junit4:junit4]   2> 741216 T2110 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372684137598/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty1/
> [junit4:junit4]   2> 741216 T2110 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@798e662b
> [junit4:junit4]   2> 741217 T2110 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty1
> [junit4:junit4]   2> 741217 T2110 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty1/index/
> [junit4:junit4]   2> 741217 T2110 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty1/index' doesn't exist. Creating new index...
> [junit4:junit4]   2> 741218 T2110 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty1/index
> [junit4:junit4]   2> 741221 T2110 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 741221 T2110 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
> [junit4:junit4]   2> 741224 T2110 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
> [junit4:junit4]   2> 741224 T2110 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
> [junit4:junit4]   2> 741225 T2110 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
> [junit4:junit4]   2> 741226 T2110 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
> [junit4:junit4]   2> 741226 T2110 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
> [junit4:junit4]   2> 741227 T2110 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
> [junit4:junit4]   2> 741227 T2110 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
> [junit4:junit4]   2> 741228 T2110 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
> [junit4:junit4]   2> 741228 T2110 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
> [junit4:junit4]   2> 741243 T2110 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
> [junit4:junit4]   2> 741250 T2110 oass.SolrIndexSearcher.<init> Opening Searcher@68a89d83 main
> [junit4:junit4]   2> 741251 T2110 oasu.CommitTracker.<init> Hard AutoCommit: disabled
> [junit4:junit4]   2> 741251 T2110 oasu.CommitTracker.<init> Soft AutoCommit: disabled
> [junit4:junit4]   2> 741255 T2111 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@68a89d83 main{StandardDirectoryReader(segments_1:1)}
> [junit4:junit4]   2> 741257 T2110 oasc.CoreContainer.registerCore registering core: collection1
> [junit4:junit4]   2> 741257 T2110 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:16933/zm/x collection:collection1 shard:shard1
> [junit4:junit4]   2> 741258 T2110 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
> [junit4:junit4]   2> 741278 T2110 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
> [junit4:junit4]   2> 741281 T2110 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
> [junit4:junit4]   2> 741281 T2110 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
> [junit4:junit4]   2> 741281 T2110 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:16933/zm/x/collection1/
> [junit4:junit4]   2> 741282 T2110 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
> [junit4:junit4]   2> 741282 T2110 oasc.SyncStrategy.syncToMe http://127.0.0.1:16933/zm/x/collection1/ has no replicas
> [junit4:junit4]   2> 741282 T2110 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:16933/zm/x/collection1/ shard1
> [junit4:junit4]   2> 741282 T2110 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
> [junit4:junit4]   2> 741286 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 741295 T2096 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> 741295 T2109 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> 741295 T2089 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> 741341 T2110 oasc.ZkController.register We are http://127.0.0.1:16933/zm/x/collection1/ and leader is http://127.0.0.1:16933/zm/x/collection1/
> [junit4:junit4]   2> 741341 T2110 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:16933/zm/x
> [junit4:junit4]   2> 741341 T2110 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
> [junit4:junit4]   2> 741341 T2110 oasc.ZkController.publish publishing core=collection1 state=active
> [junit4:junit4]   2> 741342 T2110 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 741344 T2110 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 741345 T2067 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
> [junit4:junit4]   2> 741346 T2067 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
> [junit4:junit4]   2> 741346 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
> [junit4:junit4]   2> 741609 T2067 oejs.Server.doStart jetty-8.1.10.v20130312
> [junit4:junit4]   2> 741612 T2067 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:45733
> [junit4:junit4]   2> 741613 T2067 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
> [junit4:junit4]   2> 741613 T2067 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
> [junit4:junit4]   2> 741614 T2067 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372684142204
> [junit4:junit4]   2> 741614 T2067 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372684142204/solr.xml
> [junit4:junit4]   2> 741614 T2067 oasc.CoreContainer.<init> New CoreContainer 2090646828
> [junit4:junit4]   2> 741615 T2067 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372684142204/'
> [junit4:junit4]   2> 741615 T2067 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372684142204/'
> [junit4:junit4]   2> 741736 T2067 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
> [junit4:junit4]   2> 741737 T2067 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
> [junit4:junit4]   2> 741738 T2067 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
> [junit4:junit4]   2> 741738 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
> [junit4:junit4]   2> 741739 T2067 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
> [junit4:junit4]   2> 741739 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
> [junit4:junit4]   2> 741739 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
> [junit4:junit4]   2> 741740 T2067 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
> [junit4:junit4]   2> 741740 T2067 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
> [junit4:junit4]   2> 741741 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
> [junit4:junit4]   2> 741755 T2067 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
> [junit4:junit4]   2> 741756 T2067 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:17602/solr
> [junit4:junit4]   2> 741756 T2067 oasc.ZkController.checkChrootPath zkHost includes chroot
> [junit4:junit4]   2> 741758 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 741761 T2123 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2dd83276 name:ZooKeeperConnection Watcher:127.0.0.1:17602 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 741761 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 741779 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
> [junit4:junit4]   2> 741789 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 741792 T2125 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c940331 name:ZooKeeperConnection Watcher:127.0.0.1:17602/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 741792 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 741798 T2067 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
> [junit4:junit4]   2> 742801 T2067 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45733_zm%2Fx
> [junit4:junit4]   2> 742802 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 742821 T2067 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:45733_zm%2Fx
> [junit4:junit4]   2> 742821 T2090 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:16933_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:16933/zm/x"}
> [junit4:junit4]   2> 742863 T2109 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> 742863 T2089 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> 742863 T2125 oascc.ZkStateReader$3.process Updating live nodes... (3)
> [junit4:junit4]   2> 742863 T2096 oascc.ZkStateReader$3.process Updating live nodes... (3)
> [junit4:junit4]   2> 742864 T2096 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> 742882 T2125 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> 742882 T2096 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> 742922 T2109 oascc.ZkStateReader$3.process Updating live nodes... (3)
> [junit4:junit4]   2> 742923 T2109 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> 742926 T2089 oascc.ZkStateReader$3.process Updating live nodes... (3)
> [junit4:junit4]   2> 742927 T2089 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> 742928 T2126 oasc.ZkController.publish publishing core=collection1 state=down
> [junit4:junit4]   2> 742929 T2126 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 742957 T2126 oasc.ZkController.waitForCoreNodeName look for our core node name
> [junit4:junit4]   2> 744428 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 744429 T2090 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:45733_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:45733/zm/x"}
> [junit4:junit4]   2> 744429 T2090 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
> [junit4:junit4]   2> 744429 T2090 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
> [junit4:junit4]   2> 744450 T2125 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> 744450 T2089 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> 744450 T2109 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> 744450 T2096 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> 744959 T2126 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
> [junit4:junit4]   2> 744959 T2126 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372684142204/collection1
> [junit4:junit4]   2> 744959 T2126 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
> [junit4:junit4]   2> 744960 T2126 oasc.ZkController.createCollectionZkNode Collection zkNode exists
> [junit4:junit4]   2> 744960 T2126 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
> [junit4:junit4]   2> 744962 T2126 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372684142204/collection1/'
> [junit4:junit4]   2> 744963 T2126 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372684142204/collection1/lib/README' to classloader
> [junit4:junit4]   2> 744964 T2126 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372684142204/collection1/lib/classes/' to classloader
> [junit4:junit4]   2> 745016 T2126 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
> [junit4:junit4]   2> 745078 T2126 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
> [junit4:junit4]   2> 745181 T2126 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
> [junit4:junit4]   2> 745188 T2126 oass.IndexSchema.readSchema [collection1] Schema name=test
> [junit4:junit4]   2> 745851 T2126 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
> [junit4:junit4]   2> 745863 T2126 oass.IndexSchema.readSchema default search field in schema is text
> [junit4:junit4]   2> 745867 T2126 oass.IndexSchema.readSchema unique key field: id
> [junit4:junit4]   2> 745883 T2126 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
> [junit4:junit4]   2> 745888 T2126 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
> [junit4:junit4]   2> 745892 T2126 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
> [junit4:junit4]   2> 745894 T2126 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
> [junit4:junit4]   2> 745894 T2126 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
> [junit4:junit4]   2> 745894 T2126 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
> [junit4:junit4]   2> 745896 T2126 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
> [junit4:junit4]   2> 745896 T2126 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
> [junit4:junit4]   2> 745896 T2126 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
> [junit4:junit4]   2> 745896 T2126 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372684142204/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty2/
> [junit4:junit4]   2> 745897 T2126 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@798e662b
> [junit4:junit4]   2> 745898 T2126 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty2
> [junit4:junit4]   2> 745899 T2126 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty2/index/
> [junit4:junit4]   2> 745899 T2126 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty2/index' doesn't exist. Creating new index...
> [junit4:junit4]   2> 745899 T2126 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty2/index
> [junit4:junit4]   2> 745903 T2126 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@63f3a140 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7a20d579),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 745903 T2126 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
> [junit4:junit4]   2> 745906 T2126 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
> [junit4:junit4]   2> 745906 T2126 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
> [junit4:junit4]   2> 745907 T2126 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
> [junit4:junit4]   2> 745907 T2126 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
> [junit4:junit4]   2> 745908 T2126 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
> [junit4:junit4]   2> 745908 T2126 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
> [junit4:junit4]   2> 745908 T2126 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
> [junit4:junit4]   2> 745909 T2126 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
> [junit4:junit4]   2> 745909 T2126 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
> [junit4:junit4]   2> 745924 T2126 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
> [junit4:junit4]   2> 745931 T2126 oass.SolrIndexSearcher.<init> Opening Searcher@3d1a7e9d main
> [junit4:junit4]   2> 745932 T2126 oasu.CommitTracker.<init> Hard AutoCommit: disabled
> [junit4:junit4]   2> 745933 T2126 oasu.CommitTracker.<init> Soft AutoCommit: disabled
> [junit4:junit4]   2> 745937 T2127 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d1a7e9d main{StandardDirectoryReader(segments_1:1)}
> [junit4:junit4]   2> 745939 T2126 oasc.CoreContainer.registerCore registering core: collection1
> [junit4:junit4]   2> 745939 T2126 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:45733/zm/x collection:collection1 shard:shard2
> [junit4:junit4]   2> 745940 T2126 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
> [junit4:junit4]   2> 745958 T2126 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
> [junit4:junit4]   2> 745962 T2126 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
> [junit4:junit4]   2> 745962 T2126 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
> [junit4:junit4]   2> 745962 T2126 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:45733/zm/x/collection1/
> [junit4:junit4]   2> 745962 T2126 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
> [junit4:junit4]   2> 745962 T2126 oasc.SyncStrategy.syncToMe http://127.0.0.1:45733/zm/x/collection1/ has no replicas
> [junit4:junit4]   2> 745963 T2126 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:45733/zm/x/collection1/ shard2
> [junit4:junit4]   2> 745963 T2126 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
> [junit4:junit4]   2> 747462 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 747480 T2125 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> 747480 T2096 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> 747480 T2089 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> 747480 T2109 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> 747506 T2126 oasc.ZkController.register We are http://127.0.0.1:45733/zm/x/collection1/ and leader is http://127.0.0.1:45733/zm/x/collection1/
> [junit4:junit4]   2> 747506 T2126 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45733/zm/x
> [junit4:junit4]   2> 747506 T2126 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
> [junit4:junit4]   2> 747506 T2126 oasc.ZkController.publish publishing core=collection1 state=active
> [junit4:junit4]   2> 747507 T2126 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 747508 T2126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 747510 T2067 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
> [junit4:junit4]   2> 747510 T2067 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
> [junit4:junit4]   2> 747511 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
> [junit4:junit4]   2> 747798 T2067 oejs.Server.doStart jetty-8.1.10.v20130312
> [junit4:junit4]   2> 747801 T2067 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:45777
> [junit4:junit4]   2> 747802 T2067 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
> [junit4:junit4]   2> 747802 T2067 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
> [junit4:junit4]   2> 747803 T2067 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372684148371
> [junit4:junit4]   2> 747803 T2067 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372684148371/solr.xml
> [junit4:junit4]   2> 747804 T2067 oasc.CoreContainer.<init> New CoreContainer 805132591
> [junit4:junit4]   2> 747804 T2067 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372684148371/'
> [junit4:junit4]   2> 747805 T2067 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372684148371/'
> [junit4:junit4]   2> 747936 T2067 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
> [junit4:junit4]   2> 747937 T2067 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
> [junit4:junit4]   2> 747937 T2067 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
> [junit4:junit4]   2> 747938 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
> [junit4:junit4]   2> 747938 T2067 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
> [junit4:junit4]   2> 747939 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
> [junit4:junit4]   2> 747939 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
> [junit4:junit4]   2> 747940 T2067 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
> [junit4:junit4]   2> 747940 T2067 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
> [junit4:junit4]   2> 747941 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
> [junit4:junit4]   2> 747958 T2067 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
> [junit4:junit4]   2> 747959 T2067 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:17602/solr
> [junit4:junit4]   2> 747960 T2067 oasc.ZkController.checkChrootPath zkHost includes chroot
> [junit4:junit4]   2> 747961 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 747993 T2139 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@616dff74 name:ZooKeeperConnection Watcher:127.0.0.1:17602 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 747993 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 748027 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
> [junit4:junit4]   2> 748037 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 748040 T2141 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@46e38d21 name:ZooKeeperConnection Watcher:127.0.0.1:17602/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 748040 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 748078 T2067 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
> [junit4:junit4]   2> 748987 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 748988 T2090 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:45733_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:45733/zm/x"}
> [junit4:junit4]   2> 749008 T2096 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> 749008 T2141 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> 749008 T2125 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> 749008 T2089 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> 749008 T2109 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> 749082 T2067 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45777_zm%2Fx
> [junit4:junit4]   2> 749084 T2067 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:45777_zm%2Fx
> [junit4:junit4]   2> 749087 T2109 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> 749087 T2089 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> 749088 T2096 oascc.ZkStateReader$3.process Updating live nodes... (4)
> [junit4:junit4]   2> 749087 T2141 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> 749088 T2096 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> 749088 T2125 oascc.ZkStateReader$3.process Updating live nodes... (4)
> [junit4:junit4]   2> 749089 T2125 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> 749089 T2109 oascc.ZkStateReader$3.process Updating live nodes... (4)
> [junit4:junit4]   2> 749090 T2089 oascc.ZkStateReader$3.process Updating live nodes... (4)
> [junit4:junit4]   2> 749096 T2141 oascc.ZkStateReader$3.process Updating live nodes... (4)
> [junit4:junit4]   2> 749102 T2142 oasc.ZkController.publish publishing core=collection1 state=down
> [junit4:junit4]   2> 749102 T2142 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 749104 T2142 oasc.ZkController.waitForCoreNodeName look for our core node name
> [junit4:junit4]   2> 750514 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 750515 T2090 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:45777_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:45777/zm/x"}
> [junit4:junit4]   2> 750515 T2090 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
> [junit4:junit4]   2> 750515 T2090 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
> [junit4:junit4]   2> 750533 T2096 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> 750533 T2141 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> 750533 T2089 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> 750533 T2125 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> 750533 T2109 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> 751106 T2142 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
> [junit4:junit4]   2> 751106 T2142 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372684148371/collection1
> [junit4:junit4]   2> 751106 T2142 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
> [junit4:junit4]   2> 751107 T2142 oasc.ZkController.createCollectionZkNode Collection zkNode exists
> [junit4:junit4]   2> 751107 T2142 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
> [junit4:junit4]   2> 751109 T2142 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372684148371/collection1/'
> [junit4:junit4]   2> 751110 T2142 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372684148371/collection1/lib/classes/' to classloader
> [junit4:junit4]   2> 751111 T2142 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372684148371/collection1/lib/README' to classloader
> [junit4:junit4]   2> 751163 T2142 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
> [junit4:junit4]   2> 751225 T2142 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
> [junit4:junit4]   2> 751328 T2142 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
> [junit4:junit4]   2> 751335 T2142 oass.IndexSchema.readSchema [collection1] Schema name=test
> [junit4:junit4]   2> 751970 T2142 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
> [junit4:junit4]   2> 751982 T2142 oass.IndexSchema.readSchema default search field in schema is text
> [junit4:junit4]   2> 751987 T2142 oass.IndexSchema.readSchema unique key field: id
> [junit4:junit4]   2> 752003 T2142 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
> [junit4:junit4]   2> 752008 T2142 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
> [junit4:junit4]   2> 752013 T2142 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
> [junit4:junit4]   2> 752014 T2142 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
> [junit4:junit4]   2> 752015 T2142 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
> [junit4:junit4]   2> 752015 T2142 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
> [junit4:junit4]   2> 752016 T2142 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
> [junit4:junit4]   2> 752016 T2142 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
> [junit4:junit4]   2> 752017 T2142 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
> [junit4:junit4]   2> 752017 T2142 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372684148371/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty3/
> [junit4:junit4]   2> 752017 T2142 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@798e662b
> [junit4:junit4]   2> 752018 T2142 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty3
> [junit4:junit4]   2> 752019 T2142 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty3/index/
> [junit4:junit4]   2> 752019 T2142 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty3/index' doesn't exist. Creating new index...
> [junit4:junit4]   2> 752020 T2142 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty3/index
> [junit4:junit4]   2> 752023 T2142 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@289baade lockFactory=org.apache.lucene.store.NativeFSLockFactory@62203b9),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 752024 T2142 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
> [junit4:junit4]   2> 752026 T2142 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
> [junit4:junit4]   2> 752027 T2142 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
> [junit4:junit4]   2> 752027 T2142 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
> [junit4:junit4]   2> 752028 T2142 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
> [junit4:junit4]   2> 752029 T2142 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
> [junit4:junit4]   2> 752029 T2142 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
> [junit4:junit4]   2> 752029 T2142 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
> [junit4:junit4]   2> 752030 T2142 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
> [junit4:junit4]   2> 752030 T2142 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
> [junit4:junit4]   2> 752047 T2142 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
> [junit4:junit4]   2> 752054 T2142 oass.SolrIndexSearcher.<init> Opening Searcher@70a83d7a main
> [junit4:junit4]   2> 752055 T2142 oasu.CommitTracker.<init> Hard AutoCommit: disabled
> [junit4:junit4]   2> 752056 T2142 oasu.CommitTracker.<init> Soft AutoCommit: disabled
> [junit4:junit4]   2> 752060 T2143 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@70a83d7a main{StandardDirectoryReader(segments_1:1)}
> [junit4:junit4]   2> 752062 T2142 oasc.CoreContainer.registerCore registering core: collection1
> [junit4:junit4]   2> 752062 T2142 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:45777/zm/x collection:collection1 shard:shard1
> [junit4:junit4]   2> 752066 T2142 oasc.ZkController.register We are http://127.0.0.1:45777/zm/x/collection1/ and leader is http://127.0.0.1:16933/zm/x/collection1/
> [junit4:junit4]   2> 752066 T2142 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45777/zm/x
> [junit4:junit4]   2> 752066 T2142 oasc.ZkController.checkRecovery Core needs to recover:collection1
> [junit4:junit4]   2> 752067 T2142 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
> [junit4:junit4]   2> ASYNC  NEW_CORE C991 name=collection1 org.apache.solr.core.SolrCore@53b2b3a6 url=http://127.0.0.1:45777/zm/x/collection1 node=127.0.0.1:45777_zm%2Fx C991_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:45777_zm%2Fx, base_url=http://127.0.0.1:45777/zm/x}
> [junit4:junit4]   2> 752067 T2144 C991 P45777 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
> [junit4:junit4]   2> 752068 T2142 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 752068 T2144 C991 P45777 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
> [junit4:junit4]   2> 752068 T2144 C991 P45777 oasc.ZkController.publish publishing core=collection1 state=recovering
> [junit4:junit4]   2> 752069 T2144 C991 P45777 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 752069 T2067 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
> [junit4:junit4]   2> 752070 T2067 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
> [junit4:junit4]   2> 752070 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
> [junit4:junit4]   2> 752071 T2144 C991 P45777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
> [junit4:junit4]   2> 752096 T2099 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true
> [junit4:junit4]   2> 752360 T2067 oejs.Server.doStart jetty-8.1.10.v20130312
> [junit4:junit4]   2> 752363 T2067 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:36101
> [junit4:junit4]   2> 752364 T2067 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
> [junit4:junit4]   2> 752365 T2067 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
> [junit4:junit4]   2> 752365 T2067 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372684152938
> [junit4:junit4]   2> 752366 T2067 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372684152938/solr.xml
> [junit4:junit4]   2> 752366 T2067 oasc.CoreContainer.<init> New CoreContainer 1659676005
> [junit4:junit4]   2> 752367 T2067 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372684152938/'
> [junit4:junit4]   2> 752367 T2067 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372684152938/'
> [junit4:junit4]   2> 752496 T2067 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
> [junit4:junit4]   2> 752497 T2067 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
> [junit4:junit4]   2> 752498 T2067 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
> [junit4:junit4]   2> 752498 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
> [junit4:junit4]   2> 752499 T2067 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
> [junit4:junit4]   2> 752499 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
> [junit4:junit4]   2> 752500 T2067 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
> [junit4:junit4]   2> 752500 T2067 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
> [junit4:junit4]   2> 752501 T2067 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
> [junit4:junit4]   2> 752501 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
> [junit4:junit4]   2> 752518 T2067 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
> [junit4:junit4]   2> 752519 T2067 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:17602/solr
> [junit4:junit4]   2> 752520 T2067 oasc.ZkController.checkChrootPath zkHost includes chroot
> [junit4:junit4]   2> 752521 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 752524 T2156 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3cf00b8d name:ZooKeeperConnection Watcher:127.0.0.1:17602 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 752525 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 752539 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
> [junit4:junit4]   2> 752552 T2067 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
> [junit4:junit4]   2> 752554 T2158 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6a15d897 name:ZooKeeperConnection Watcher:127.0.0.1:17602/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
> [junit4:junit4]   2> 752555 T2067 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
> [junit4:junit4]   2> 752566 T2067 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
> [junit4:junit4]   2> 753541 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 753542 T2090 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:45777_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:45777/zm/x"}
> [junit4:junit4]   2> 753550 T2096 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> 753550 T2141 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> 753550 T2089 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> 753550 T2109 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> 753550 T2158 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> 753550 T2125 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> 753571 T2067 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36101_zm%2Fx
> [junit4:junit4]   2> 753573 T2067 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36101_zm%2Fx
> [junit4:junit4]   2> 753576 T2109 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> 753576 T2089 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> 753576 T2096 oascc.ZkStateReader$3.process Updating live nodes... (5)
> [junit4:junit4]   2> 753576 T2141 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> 753576 T2158 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> 753576 T2096 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> 753576 T2125 oascc.ZkStateReader$3.process Updating live nodes... (5)
> [junit4:junit4]   2> 753577 T2125 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> 753578 T2109 oascc.ZkStateReader$3.process Updating live nodes... (5)
> [junit4:junit4]   2> 753578 T2089 oascc.ZkStateReader$3.process Updating live nodes... (5)
> [junit4:junit4]   2> 753579 T2141 oascc.ZkStateReader$3.process Updating live nodes... (5)
> [junit4:junit4]   2> 753579 T2158 oascc.ZkStateReader$3.process Updating live nodes... (5)
> [junit4:junit4]   2> 753585 T2159 oasc.ZkController.publish publishing core=collection1 state=down
> [junit4:junit4]   2> 753585 T2159 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 753587 T2159 oasc.ZkController.waitForCoreNodeName look for our core node name
> [junit4:junit4]   2> 754099 T2099 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
> [junit4:junit4]   2> 754099 T2099 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node3&state=recovering&nodeName=127.0.0.1:45777_zm%252Fx&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003 
> [junit4:junit4]   2> 755065 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 755066 T2090 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:36101_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36101/zm/x"}
> [junit4:junit4]   2> 755066 T2090 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
> [junit4:junit4]   2> 755066 T2090 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
> [junit4:junit4]   2> 755072 T2125 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> 755072 T2141 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> 755072 T2089 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> 755072 T2109 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> 755072 T2158 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> 755072 T2096 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> 755590 T2159 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
> [junit4:junit4]   2> 755590 T2159 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372684152938/collection1
> [junit4:junit4]   2> 755590 T2159 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
> [junit4:junit4]   2> 755591 T2159 oasc.ZkController.createCollectionZkNode Collection zkNode exists
> [junit4:junit4]   2> 755592 T2159 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
> [junit4:junit4]   2> 755593 T2159 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372684152938/collection1/'
> [junit4:junit4]   2> 755595 T2159 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372684152938/collection1/lib/README' to classloader
> [junit4:junit4]   2> 755595 T2159 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372684152938/collection1/lib/classes/' to classloader
> [junit4:junit4]   2> 755647 T2159 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
> [junit4:junit4]   2> 755709 T2159 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
> [junit4:junit4]   2> 755812 T2159 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
> [junit4:junit4]   2> 755819 T2159 oass.IndexSchema.readSchema [collection1] Schema name=test
> [junit4:junit4]   2> ASYNC  NEW_CORE C992 name=collection1 org.apache.solr.core.SolrCore@53b2b3a6 url=http://127.0.0.1:45777/zm/x/collection1 node=127.0.0.1:45777_zm%2Fx C992_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:45777_zm%2Fx, base_url=http://127.0.0.1:45777/zm/x}
> [junit4:junit4]   2> 756102 T2144 C992 P45777 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:16933/zm/x/collection1/ core=collection1 - recoveringAfterStartup=true
> [junit4:junit4]   2> 756102 T2144 C992 P45777 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:45777/zm/x START replicas=[http://127.0.0.1:16933/zm/x/collection1/] nUpdates=100
> [junit4:junit4]   2> 756103 T2144 C992 P45777 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
> [junit4:junit4]   2> 756103 T2144 C992 P45777 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
> [junit4:junit4]   2> 756103 T2144 C992 P45777 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
> [junit4:junit4]   2> 756104 T2144 C992 P45777 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
> [junit4:junit4]   2> 756104 T2144 C992 P45777 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
> [junit4:junit4]   2> 756104 T2144 C992 P45777 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:16933/zm/x/collection1/. core=collection1
> [junit4:junit4]   2> 756105 T2144 C992 P45777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
> [junit4:junit4]   2> ASYNC  NEW_CORE C993 name=collection1 org.apache.solr.core.SolrCore@215eb2d8 url=http://127.0.0.1:16933/zm/x/collection1 node=127.0.0.1:16933_zm%2Fx C993_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:16933_zm%2Fx, base_url=http://127.0.0.1:16933/zm/x, leader=true}
> [junit4:junit4]   2> 756113 T2100 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
> [junit4:junit4]   2> 756116 T2101 C993 P16933 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 756119 T2101 C993 P16933 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 756120 T2101 C993 P16933 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
> [junit4:junit4]   2> 756120 T2101 C993 P16933 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
> [junit4:junit4]   2> 756121 T2101 C993 P16933 oass.SolrIndexSearcher.<init> Opening Searcher@4d16c784 realtime
> [junit4:junit4]   2> 756121 T2101 C993 P16933 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 756122 T2101 C993 P16933 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
> [junit4:junit4]   2> 756122 T2144 C992 P45777 oash.ReplicationHandler.inform Commits will be reserved for  10000
> [junit4:junit4]   2> 756123 T2144 C992 P45777 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
> [junit4:junit4]   2> 756125 T2102 C993 P16933 oash.ReplicationHandler.inform Commits will be reserved for  10000
> [junit4:junit4]   2> 756125 T2102 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
> [junit4:junit4]   2> 756126 T2144 C992 P45777 oasc.RecoveryStrategy.replay No replay needed. core=collection1
> [junit4:junit4]   2> 756126 T2144 C992 P45777 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
> [junit4:junit4]   2> 756126 T2144 C992 P45777 oasc.ZkController.publish publishing core=collection1 state=active
> [junit4:junit4]   2> 756126 T2144 C992 P45777 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 756128 T2144 C992 P45777 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
> [junit4:junit4]   2> 756453 T2159 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
> [junit4:junit4]   2> 756466 T2159 oass.IndexSchema.readSchema default search field in schema is text
> [junit4:junit4]   2> 756470 T2159 oass.IndexSchema.readSchema unique key field: id
> [junit4:junit4]   2> 756487 T2159 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
> [junit4:junit4]   2> 756492 T2159 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
> [junit4:junit4]   2> 756496 T2159 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
> [junit4:junit4]   2> 756498 T2159 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
> [junit4:junit4]   2> 756498 T2159 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
> [junit4:junit4]   2> 756499 T2159 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
> [junit4:junit4]   2> 756500 T2159 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
> [junit4:junit4]   2> 756500 T2159 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
> [junit4:junit4]   2> 756500 T2159 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
> [junit4:junit4]   2> 756501 T2159 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372684152938/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty4/
> [junit4:junit4]   2> 756501 T2159 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@798e662b
> [junit4:junit4]   2> 756502 T2159 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty4
> [junit4:junit4]   2> 756502 T2159 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty4/index/
> [junit4:junit4]   2> 756503 T2159 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty4/index' doesn't exist. Creating new index...
> [junit4:junit4]   2> 756503 T2159 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372684133825/jetty4/index
> [junit4:junit4]   2> 756507 T2159 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3fb835d1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fdaa1ee),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 756507 T2159 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
> [junit4:junit4]   2> 756510 T2159 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
> [junit4:junit4]   2> 756510 T2159 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
> [junit4:junit4]   2> 756511 T2159 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
> [junit4:junit4]   2> 756512 T2159 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
> [junit4:junit4]   2> 756512 T2159 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
> [junit4:junit4]   2> 756512 T2159 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
> [junit4:junit4]   2> 756513 T2159 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
> [junit4:junit4]   2> 756514 T2159 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
> [junit4:junit4]   2> 756514 T2159 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
> [junit4:junit4]   2> 756531 T2159 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
> [junit4:junit4]   2> 756538 T2159 oass.SolrIndexSearcher.<init> Opening Searcher@37878dd4 main
> [junit4:junit4]   2> 756539 T2159 oasu.CommitTracker.<init> Hard AutoCommit: disabled
> [junit4:junit4]   2> 756539 T2159 oasu.CommitTracker.<init> Soft AutoCommit: disabled
> [junit4:junit4]   2> 756544 T2161 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@37878dd4 main{StandardDirectoryReader(segments_1:1)}
> [junit4:junit4]   2> 756546 T2159 oasc.CoreContainer.registerCore registering core: collection1
> [junit4:junit4]   2> 756546 T2159 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36101/zm/x collection:collection1 shard:shard2
> [junit4:junit4]   2> 756550 T2159 oasc.ZkController.register We are http://127.0.0.1:36101/zm/x/collection1/ and leader is http://127.0.0.1:45733/zm/x/collection1/
> [junit4:junit4]   2> 756550 T2159 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36101/zm/x
> [junit4:junit4]   2> 756550 T2159 oasc.ZkController.checkRecovery Core needs to recover:collection1
> [junit4:junit4]   2> 756550 T2159 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
> [junit4:junit4]   2> ASYNC  NEW_CORE C994 name=collection1 org.apache.solr.core.SolrCore@7f9607f7 url=http://127.0.0.1:36101/zm/x/collection1 node=127.0.0.1:36101_zm%2Fx C994_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:36101_zm%2Fx, base_url=http://127.0.0.1:36101/zm/x}
> [junit4:junit4]   2> 756551 T2162 C994 P36101 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
> [junit4:junit4]   2> 756551 T2162 C994 P36101 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
> [junit4:junit4]   2> 756551 T2159 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 756552 T2162 C994 P36101 oasc.ZkController.publish publishing core=collection1 state=recovering
> [junit4:junit4]   2> 756552 T2162 C994 P36101 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 756553 T2067 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
> [junit4:junit4]   2> 756553 T2067 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
> [junit4:junit4]   2> 756553 T2162 C994 P36101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
> [junit4:junit4]   2> 756554 T2067 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
> [junit4:junit4]   2> 756572 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 756573 T2115 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true
> [junit4:junit4]   2> 756574 T2067 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):330
> [junit4:junit4]   2> 756575 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 756585 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 756585 T2090 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:45777_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:45777/zm/x"}
> [junit4:junit4]   2> 756590 T2090 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:36101_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36101/zm/x"}
> [junit4:junit4]   2> 756601 T2096 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> 756602 T2141 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> 756602 T2158 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> 756602 T2089 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> 756601 T2109 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> 756601 T2125 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> 757575 T2115 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
> [junit4:junit4]   2> 757575 T2115 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node4&state=recovering&nodeName=127.0.0.1:36101_zm%252Fx&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002 
> [junit4:junit4]   2> 757578 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 758581 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2>  C994_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:36101_zm%2Fx, base_url=http://127.0.0.1:36101/zm/x}
> [junit4:junit4]   2> 759578 T2162 C994 P36101 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:45733/zm/x/collection1/ core=collection1 - recoveringAfterStartup=true
> [junit4:junit4]   2> 759578 T2162 C994 P36101 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:36101/zm/x START replicas=[http://127.0.0.1:45733/zm/x/collection1/] nUpdates=100
> [junit4:junit4]   2> 759579 T2162 C994 P36101 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
> [junit4:junit4]   2> 759579 T2162 C994 P36101 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
> [junit4:junit4]   2> 759579 T2162 C994 P36101 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
> [junit4:junit4]   2> 759579 T2162 C994 P36101 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
> [junit4:junit4]   2> 759580 T2162 C994 P36101 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
> [junit4:junit4]   2> 759580 T2162 C994 P36101 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:45733/zm/x/collection1/. core=collection1
> [junit4:junit4]   2> 759581 T2162 C994 P36101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
> [junit4:junit4]   2> 759584 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> ASYNC  NEW_CORE C995 name=collection1 org.apache.solr.core.SolrCore@1e8d62e0 url=http://127.0.0.1:45733/zm/x/collection1 node=127.0.0.1:45733_zm%2Fx C995_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:45733_zm%2Fx, base_url=http://127.0.0.1:45733/zm/x, leader=true}
> [junit4:junit4]   2> 759588 T2116 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
> [junit4:junit4]   2> 759592 T2117 C995 P45733 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 759594 T2117 C995 P45733 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@63f3a140 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7a20d579),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 759596 T2117 C995 P45733 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
> [junit4:junit4]   2> 759596 T2117 C995 P45733 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
> [junit4:junit4]   2> 759597 T2117 C995 P45733 oass.SolrIndexSearcher.<init> Opening Searcher@496ac93a realtime
> [junit4:junit4]   2> 759597 T2117 C995 P45733 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 759597 T2117 C995 P45733 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
> [junit4:junit4]   2> 759598 T2162 C994 P36101 oash.ReplicationHandler.inform Commits will be reserved for  10000
> [junit4:junit4]   2> 759598 T2162 C994 P36101 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
> [junit4:junit4]   2> 759600 T2118 C995 P45733 oash.ReplicationHandler.inform Commits will be reserved for  10000
> [junit4:junit4]   2> 759600 T2118 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
> [junit4:junit4]   2> 759601 T2162 C994 P36101 oasc.RecoveryStrategy.replay No replay needed. core=collection1
> [junit4:junit4]   2> 759601 T2162 C994 P36101 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
> [junit4:junit4]   2> 759601 T2162 C994 P36101 oasc.ZkController.publish publishing core=collection1 state=active
> [junit4:junit4]   2> 759602 T2162 C994 P36101 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
> [junit4:junit4]   2> 759639 T2162 C994 P36101 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
> [junit4:junit4]   2> 759641 T2090 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 759642 T2090 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:36101_zm%2Fx",
> [junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36101/zm/x"}
> [junit4:junit4]   2> 759653 T2125 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> 759653 T2141 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> 759653 T2089 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> 759653 T2109 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> 759653 T2158 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> 759653 T2096 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> 760586 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760587 T2067 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
> [junit4:junit4]   2> ASYNC  NEW_CORE C996 name=collection1 org.apache.solr.core.SolrCore@565d49dc url=http://127.0.0.1:19896/zm/x/collection1 node=127.0.0.1:19896_zm%2Fx C996_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:19896_zm%2Fx, base_url=http://127.0.0.1:19896/zm/x, leader=true}
> [junit4:junit4]   2> 760599 T2079 C996 P19896 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@47d81405 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79787b31),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 760600 T2079 C996 P19896 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
> [junit4:junit4]   2> 760602 T2079 C996 P19896 oass.SolrIndexSearcher.<init> Opening Searcher@462edf25 realtime
> [junit4:junit4]   2> 760602 T2079 C996 P19896 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439363667266109440)} 0 6
> [junit4:junit4]   2>  C994_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:36101_zm%2Fx, base_url=http://127.0.0.1:36101/zm/x}
> [junit4:junit4]   2> 760626 T2148 C994 P36101 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3fb835d1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fdaa1ee),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 760627 T2148 C994 P36101 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
> [junit4:junit4]   2> 760629 T2148 C994 P36101 oass.SolrIndexSearcher.<init> Opening Searcher@2c01e8e2 realtime
> [junit4:junit4]   2> 760629 T2148 C994 P36101 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={update.distrib=FROMLEADER&_version_=-1439363667282886656&update.from=http://127.0.0.1:45733/zm/x/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439363667282886656)} 0 4
> [junit4:junit4]   2>  C992_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:45777_zm%2Fx, base_url=http://127.0.0.1:45777/zm/x}
> [junit4:junit4]   2> 760630 T2131 C992 P45777 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@289baade lockFactory=org.apache.lucene.store.NativeFSLockFactory@62203b9),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 760631 T2131 C992 P45777 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
> [junit4:junit4]   2> 760632 T2131 C992 P45777 oass.SolrIndexSearcher.<init> Opening Searcher@6925ec4e realtime
> [junit4:junit4]   2> 760633 T2131 C992 P45777 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={update.distrib=FROMLEADER&_version_=-1439363667287080960&update.from=http://127.0.0.1:16933/zm/x/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439363667287080960)} 0 5
> [junit4:junit4]   2> 760634 T2103 C993 P16933 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1439363667287080960)} 0 17
> [junit4:junit4]   2> 760634 T2119 C995 P45733 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439363667282886656)} 0 21
> [junit4:junit4]   2> 760636 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760638 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760640 T2104 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=0 
> [junit4:junit4]   2> 760642 T2132 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=0 
> [junit4:junit4]   2> 760643 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760646 T2120 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=0 
> [junit4:junit4]   2> 760648 T2149 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=0 
> [junit4:junit4]   2> 760652 T2079 C996 P19896 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760674 T2079 C996 P19896 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@47d81405 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79787b31),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@47d81405 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79787b31),segFN=segments_2,generation=2}
> [junit4:junit4]   2> 760675 T2079 C996 P19896 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
> [junit4:junit4]   2> 760681 T2079 C996 P19896 oass.SolrIndexSearcher.<init> Opening Searcher@190c0090 main
> [junit4:junit4]   2> 760681 T2079 C996 P19896 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760682 T2093 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@190c0090 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
> [junit4:junit4]   2> 760682 T2079 C996 P19896 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439363667322732544)],commit=} 0 31
> [junit4:junit4]   2> 760689 T2131 C992 P45777 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={distrib.from=http://127.0.0.1:16933/zm/x/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439363667358384128)]} 0 1
> [junit4:junit4]   2> 760690 T2104 C993 P16933 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:16933/zm/x/collection1/, StdNode: http://127.0.0.1:45777/zm/x/collection1/, StdNode: http://127.0.0.1:45733/zm/x/collection1/, StdNode: http://127.0.0.1:36101/zm/x/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
> [junit4:junit4]   2> 760692 T2105 C993 P16933 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760692 T2121 C995 P45733 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760692 T2150 C994 P36101 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760693 T2131 C992 P45777 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760693 T2150 C994 P36101 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
> [junit4:junit4]   2> 760693 T2121 C995 P45733 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
> [junit4:junit4]   2> 760695 T2150 C994 P36101 oass.SolrIndexSearcher.<init> Opening Searcher@693e8ddf main
> [junit4:junit4]   2> 760696 T2105 C993 P16933 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_2,generation=2}
> [junit4:junit4]   2> 760696 T2121 C995 P45733 oass.SolrIndexSearcher.<init> Opening Searcher@10432ba8 main
> [junit4:junit4]   2> 760697 T2131 C992 P45777 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@289baade lockFactory=org.apache.lucene.store.NativeFSLockFactory@62203b9),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@289baade lockFactory=org.apache.lucene.store.NativeFSLockFactory@62203b9),segFN=segments_2,generation=2}
> [junit4:junit4]   2> 760697 T2161 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@693e8ddf main{StandardDirectoryReader(segments_1:1:nrt)}
> [junit4:junit4]   2> 760696 T2105 C993 P16933 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
> [junit4:junit4]   2> 760696 T2150 C994 P36101 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760698 T2127 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10432ba8 main{StandardDirectoryReader(segments_1:1:nrt)}
> [junit4:junit4]   2> 760697 T2131 C992 P45777 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
> [junit4:junit4]   2> 760697 T2121 C995 P45733 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760699 T2105 C993 P16933 oass.SolrIndexSearcher.<init> Opening Searcher@6a162992 main
> [junit4:junit4]   2> 760698 T2150 C994 P36101 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
> [junit4:junit4]   2> 760700 T2105 C993 P16933 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760700 T2131 C992 P45777 oass.SolrIndexSearcher.<init> Opening Searcher@64c26d35 main
> [junit4:junit4]   2> 760700 T2121 C995 P45733 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
> [junit4:junit4]   2> 760701 T2131 C992 P45777 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760701 T2111 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6a162992 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
> [junit4:junit4]   2> 760702 T2143 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@64c26d35 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
> [junit4:junit4]   2> 760702 T2105 C993 P16933 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
> [junit4:junit4]   2> 760703 T2131 C992 P45777 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
> [junit4:junit4]   2> 760703 T2104 C993 P16933 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439363667358384128)],commit=} 0 18
> [junit4:junit4]   2> 760705 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760707 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760712 T2104 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760715 T2132 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760717 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760720 T2120 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760723 T2149 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760724 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760726 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760732 T2099 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161572&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760732 T2115 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161572&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760736 T2099 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161572&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760737 T2104 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=8 
> [junit4:junit4]   2> 760743 T2101 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161583&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760743 T2117 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161583&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760746 T2101 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161583&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760747 T2132 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7 
> [junit4:junit4]   2> 760749 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760755 T2177 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161595&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760755 T2178 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161595&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760759 T2177 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161595&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760760 T2120 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=8 
> [junit4:junit4]   2> 760766 T2181 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161606&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760766 T2182 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161606&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760769 T2181 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161606&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760770 T2149 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7 
> [junit4:junit4]   2> 760775 T2079 C996 P19896 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760778 T2079 C996 P19896 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@47d81405 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79787b31),segFN=segments_2,generation=2}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@47d81405 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79787b31),segFN=segments_3,generation=3}
> [junit4:junit4]   2> 760779 T2079 C996 P19896 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
> [junit4:junit4]   2> 760780 T2079 C996 P19896 oass.SolrIndexSearcher.<init> Opening Searcher@54bd13e5 main
> [junit4:junit4]   2> 760781 T2079 C996 P19896 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760781 T2093 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@54bd13e5 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
> [junit4:junit4]   2> 760782 T2079 C996 P19896 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439363667450658816)],commit=} 0 9
> [junit4:junit4]   2> 760795 T2131 C992 P45777 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={distrib.from=http://127.0.0.1:16933/zm/x/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439363667467436032)]} 0 2
> [junit4:junit4]   2> 760796 T2103 C993 P16933 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={distrib.from=http://127.0.0.1:45733/zm/x/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439363667467436032)]} 0 8
> [junit4:junit4]   2> 760796 T2120 C995 P45733 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:16933/zm/x/collection1/, StdNode: http://127.0.0.1:45777/zm/x/collection1/, StdNode: http://127.0.0.1:45733/zm/x/collection1/, StdNode: http://127.0.0.1:36101/zm/x/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
> [junit4:junit4]   2> 760798 T2133 C992 P45777 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760798 T2185 C995 P45733 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760800 T2185 C995 P45733 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
> [junit4:junit4]   2> 760800 T2185 C995 P45733 oass.SolrIndexSearcher.<init> Opening Searcher@17b4c540 main
> [junit4:junit4]   2> 760800 T2148 C994 P36101 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760800 T2103 C993 P16933 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760802 T2127 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@17b4c540 main{StandardDirectoryReader(segments_1:1:nrt)}
> [junit4:junit4]   2> 760802 T2148 C994 P36101 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
> [junit4:junit4]   2> 760801 T2185 C995 P45733 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760803 T2148 C994 P36101 oass.SolrIndexSearcher.<init> Opening Searcher@67e514d main
> [junit4:junit4]   2> 760803 T2133 C992 P45777 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@289baade lockFactory=org.apache.lucene.store.NativeFSLockFactory@62203b9),segFN=segments_2,generation=2}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@289baade lockFactory=org.apache.lucene.store.NativeFSLockFactory@62203b9),segFN=segments_3,generation=3}
> [junit4:junit4]   2> 760804 T2148 C994 P36101 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760804 T2185 C995 P45733 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
> [junit4:junit4]   2> 760805 T2103 C993 P16933 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_2,generation=2}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_3,generation=3}
> [junit4:junit4]   2> 760805 T2161 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@67e514d main{StandardDirectoryReader(segments_1:1:nrt)}
> [junit4:junit4]   2> 760805 T2133 C992 P45777 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
> [junit4:junit4]   2> 760807 T2148 C994 P36101 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
> [junit4:junit4]   2> 760806 T2103 C993 P16933 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
> [junit4:junit4]   2> 760808 T2133 C992 P45777 oass.SolrIndexSearcher.<init> Opening Searcher@3cd97ef4 main
> [junit4:junit4]   2> 760809 T2133 C992 P45777 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760809 T2103 C993 P16933 oass.SolrIndexSearcher.<init> Opening Searcher@1ec58f94 main
> [junit4:junit4]   2> 760810 T2143 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3cd97ef4 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
> [junit4:junit4]   2> 760810 T2103 C993 P16933 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760810 T2133 C992 P45777 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
> [junit4:junit4]   2> 760811 T2111 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ec58f94 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
> [junit4:junit4]   2> 760811 T2103 C993 P16933 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x 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> 760812 T2120 C995 P45733 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 27
> [junit4:junit4]   2> 760813 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760815 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760819 T2104 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760823 T2132 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760824 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760828 T2120 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760832 T2149 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760833 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760835 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760841 T2115 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161681&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760841 T2099 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161681&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760846 T2099 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161681&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760847 T2104 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760853 T2117 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161693&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760853 T2101 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161693&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760857 T2101 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161693&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760858 T2132 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=8 
> [junit4:junit4]   2> 760859 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760866 T2178 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161706&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760866 T2177 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161706&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760870 T2177 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161706&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760871 T2120 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=8 
> [junit4:junit4]   2> 760877 T2182 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161717&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760878 T2181 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161717&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760882 T2181 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161717&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760883 T2149 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760889 T2079 C996 P19896 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760892 T2079 C996 P19896 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@47d81405 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79787b31),segFN=segments_3,generation=3}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@47d81405 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79787b31),segFN=segments_4,generation=4}
> [junit4:junit4]   2> 760893 T2079 C996 P19896 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
> [junit4:junit4]   2> 760894 T2079 C996 P19896 oass.SolrIndexSearcher.<init> Opening Searcher@3b31fd2f main
> [junit4:junit4]   2> 760895 T2079 C996 P19896 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760895 T2093 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3b31fd2f main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):C1)}
> [junit4:junit4]   2> 760896 T2079 C996 P19896 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439363667570196480)],commit=} 0 9
> [junit4:junit4]   2> 760907 T2131 C992 P45777 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={distrib.from=http://127.0.0.1:16933/zm/x/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439363667584876544)]} 0 2
> [junit4:junit4]   2> 760908 T2187 C993 P16933 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={distrib.from=http://127.0.0.1:45777/zm/x/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439363667584876544)]} 0 7
> [junit4:junit4]   2> 760908 T2132 C992 P45777 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:16933/zm/x/collection1/, StdNode: http://127.0.0.1:45777/zm/x/collection1/, StdNode: http://127.0.0.1:45733/zm/x/collection1/, StdNode: http://127.0.0.1:36101/zm/x/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
> [junit4:junit4]   2> 760911 T2134 C992 P45777 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760911 T2191 C995 P45733 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760911 T2187 C993 P16933 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760911 T2151 C994 P36101 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760912 T2191 C995 P45733 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
> [junit4:junit4]   2> 760913 T2151 C994 P36101 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
> [junit4:junit4]   2> 760913 T2191 C995 P45733 oass.SolrIndexSearcher.<init> Opening Searcher@5dcf10fa main
> [junit4:junit4]   2> 760914 T2134 C992 P45777 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@289baade lockFactory=org.apache.lucene.store.NativeFSLockFactory@62203b9),segFN=segments_3,generation=3}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@289baade lockFactory=org.apache.lucene.store.NativeFSLockFactory@62203b9),segFN=segments_4,generation=4}
> [junit4:junit4]   2> 760914 T2151 C994 P36101 oass.SolrIndexSearcher.<init> Opening Searcher@70a07912 main
> [junit4:junit4]   2> 760915 T2127 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5dcf10fa main{StandardDirectoryReader(segments_1:1:nrt)}
> [junit4:junit4]   2> 760915 T2187 C993 P16933 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_3,generation=3}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_4,generation=4}
> [junit4:junit4]   2> 760916 T2161 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@70a07912 main{StandardDirectoryReader(segments_1:1:nrt)}
> [junit4:junit4]   2> 760914 T2134 C992 P45777 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
> [junit4:junit4]   2> 760914 T2191 C995 P45733 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760916 T2187 C993 P16933 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
> [junit4:junit4]   2> 760915 T2151 C994 P36101 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760917 T2134 C992 P45777 oass.SolrIndexSearcher.<init> Opening Searcher@6b4a3fc7 main
> [junit4:junit4]   2> 760917 T2191 C995 P45733 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
> [junit4:junit4]   2> 760918 T2134 C992 P45777 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760918 T2187 C993 P16933 oass.SolrIndexSearcher.<init> Opening Searcher@5338fea9 main
> [junit4:junit4]   2> 760918 T2151 C994 P36101 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
> [junit4:junit4]   2> 760919 T2187 C993 P16933 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760919 T2143 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6b4a3fc7 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):C1)}
> [junit4:junit4]   2> 760920 T2111 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5338fea9 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):C1)}
> [junit4:junit4]   2> 760921 T2134 C992 P45777 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
> [junit4:junit4]   2> 760921 T2187 C993 P16933 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
> [junit4:junit4]   2> 760922 T2132 C992 P45777 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 24
> [junit4:junit4]   2> 760923 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760925 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760929 T2104 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760931 T2132 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760933 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760936 T2120 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760939 T2149 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 760940 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760942 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760948 T2135 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161789&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760949 T2115 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161789&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760952 T2135 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161789&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760953 T2104 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7 
> [junit4:junit4]   2> 760958 T2136 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161799&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760959 T2117 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161799&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760962 T2136 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161799&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760963 T2132 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7 
> [junit4:junit4]   2> 760964 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 760970 T2137 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161811&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760972 T2178 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161811&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760975 T2137 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161811&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760976 T2120 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=8 
> [junit4:junit4]   2> 760981 T2192 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161822&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760982 T2182 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161822&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 760985 T2192 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161822&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 760986 T2149 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7 
> [junit4:junit4]   2> 760991 T2079 C996 P19896 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 760994 T2079 C996 P19896 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@47d81405 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79787b31),segFN=segments_4,generation=4}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@47d81405 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79787b31),segFN=segments_5,generation=5}
> [junit4:junit4]   2> 760994 T2079 C996 P19896 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
> [junit4:junit4]   2> 760996 T2079 C996 P19896 oass.SolrIndexSearcher.<init> Opening Searcher@5657776 main
> [junit4:junit4]   2> 760996 T2079 C996 P19896 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 760997 T2093 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5657776 main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):C1)}
> [junit4:junit4]   2> 760998 T2079 C996 P19896 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439363667677151232)],commit=} 0 9
> [junit4:junit4]   2> 761009 T2131 C992 P45777 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={distrib.from=http://127.0.0.1:16933/zm/x/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439363667691831296)]} 0 2
> [junit4:junit4]   2> 761010 T2194 C993 P16933 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={distrib.from=http://127.0.0.1:36101/zm/x/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439363667691831296)]} 0 7
> [junit4:junit4]   2> 761010 T2149 C994 P36101 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:16933/zm/x/collection1/, StdNode: http://127.0.0.1:45777/zm/x/collection1/, StdNode: http://127.0.0.1:45733/zm/x/collection1/, StdNode: http://127.0.0.1:36101/zm/x/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
> [junit4:junit4]   2> 761013 T2198 C992 P45777 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 761013 T2194 C993 P16933 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 761013 T2152 C994 P36101 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 761013 T2199 C995 P45733 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> [junit4:junit4]   2> 761014 T2152 C994 P36101 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
> [junit4:junit4]   2> 761014 T2199 C995 P45733 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
> [junit4:junit4]   2> 761015 T2152 C994 P36101 oass.SolrIndexSearcher.<init> Opening Searcher@4ba28ccb main
> [junit4:junit4]   2> 761015 T2199 C995 P45733 oass.SolrIndexSearcher.<init> Opening Searcher@2d76073e main
> [junit4:junit4]   2> 761016 T2194 C993 P16933 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_1,generation=1}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_4,generation=4}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ea62959 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8517ccb),segFN=segments_5,generation=5}
> [junit4:junit4]   2> 761017 T2161 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4ba28ccb main{StandardDirectoryReader(segments_1:1:nrt)}
> [junit4:junit4]   2> 761017 T2127 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d76073e main{StandardDirectoryReader(segments_1:1:nrt)}
> [junit4:junit4]   2> 761016 T2199 C995 P45733 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 761016 T2198 C992 P45777 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@289baade lockFactory=org.apache.lucene.store.NativeFSLockFactory@62203b9),segFN=segments_4,generation=4}
> [junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@289baade lockFactory=org.apache.lucene.store.NativeFSLockFactory@62203b9),segFN=segments_5,generation=5}
> [junit4:junit4]   2> 761016 T2152 C994 P36101 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 761018 T2198 C992 P45777 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
> [junit4:junit4]   2> 761018 T2199 C995 P45733 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
> [junit4:junit4]   2> 761017 T2194 C993 P16933 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
> [junit4:junit4]   2> 761018 T2152 C994 P36101 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
> [junit4:junit4]   2> 761020 T2198 C992 P45777 oass.SolrIndexSearcher.<init> Opening Searcher@23594073 main
> [junit4:junit4]   2> 761021 T2194 C993 P16933 oass.SolrIndexSearcher.<init> Opening Searcher@3b4fcbaa main
> [junit4:junit4]   2> 761021 T2198 C992 P45777 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 761021 T2143 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@23594073 main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):C1)}
> [junit4:junit4]   2> 761021 T2194 C993 P16933 oasu.DirectUpdateHandler2.commit end_commit_flush
> [junit4:junit4]   2> 761022 T2198 C992 P45777 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x 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> 761022 T2111 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3b4fcbaa main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):C1)}
> [junit4:junit4]   2> 761023 T2194 C993 P16933 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
> [junit4:junit4]   2> 761024 T2149 C994 P36101 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 24
> [junit4:junit4]   2> 761025 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 761027 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 761030 T2104 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 761033 T2132 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 761035 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 761038 T2120 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 761041 T2149 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 761042 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 761044 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 761049 T2153 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161890&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 761050 T2135 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161890&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 761053 T2135 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161890&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 761054 T2104 C993 P16933 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7 
> [junit4:junit4]   2> 761060 T2154 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161901&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 761061 T2136 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161901&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 761064 T2136 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161901&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 761065 T2132 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7 
> [junit4:junit4]   2> 761066 T2067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
> [junit4:junit4]   2> 761073 T2200 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161914&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 761075 T2137 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161914&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 761079 T2137 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161914&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 761080 T2120 C995 P45733 oasc.SolrCore.execute [collection1] webapp=/zm/x 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> 761085 T2201 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161926&shard.url=127.0.0.1:45733/zm/x/collection1/|127.0.0.1:36101/zm/x/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> 761086 T2192 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161926&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 761089 T2192 C992 P45777 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={NOW=1372684161926&shard.url=127.0.0.1:16933/zm/x/collection1/|127.0.0.1:45777/zm/x/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> 761090 T2149 C994 P36101 oasc.SolrCore.execute [collection1] webapp=/zm/x path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7 
> [junit4:junit4]   2> 761098 T2079 C996 P19896 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={wt=javabin&version=2} {add=[1 (1439363667787251712)]} 0 4
> [junit4:junit4]   2> 761111 T2131 C992 P45777 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={distrib.from=http://127.0.0.1:16933/zm/x/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439363667796688896)]} 0 3
> [junit4:junit4]   2> 761112 T2103 C993 P16933 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={distrib.from=http://127.0.0.1:45733/zm/x/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439363667796688896)]} 0 9
> [junit4:junit4]   2> 761112 T2119 C995 P45733 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={wt=javabin&version=2} {add=[1]} 0 12
> [junit4:junit4]   2> 761116 T2079 C996 P19896 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={wt=javabin&version=2} {add=[2 (1439363667809271808)]} 0 1
> [junit4:junit4]   2> 761128 T2148 C994 P36101 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={distrib.from=http://127.0.0.1:45733/zm/x/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1439363667813466112)]} 0 3
> [junit4:junit4]   2> 761128 T2119 C995 P45733 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={wt=javabin&version=2} {add=[2 (1439363667813466112)]} 0 9
> [junit4:junit4]   2> 761132 T2079 C996 P19896 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={wt=javabin&version=2} {add=[3 (1439363667826049024)]} 0 1
> [junit4:junit4]   2> 761140 T2148 C994 P36101 oasup.LogUpdateProcessor.finish [collection1] webapp=/zm/x path=/update params={distrib.from=http://127.0.0.1:45733/zm/x/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1439363667830243328)]} 0 1
> [junit4:junit4]   2> 761141 T2119 C995 P4573
> 
> [...truncated too long message...]
> 
> TestBloomFilteredLucene41Postings), id=PostingsFormat(name=Memory doPackFST= true), range_facet_sl=PostingsFormat(name=Memory doPackFST= true), range_facet_si=PostingsFormat(name=TestBloomFilteredLucene41Postings), oddField_s=PostingsFormat(name=Memory doPackFST= true), sequence_i=PostingsFormat(name=Memory doPackFST= true), name=PostingsFormat(name=Memory doPackFST= true), foo_i=PostingsFormat(name=SimpleText), regex_dup_B_s=PostingsFormat(name=TestBloomFilteredLucene41Postings), multiDefault=PostingsFormat(name=TestBloomFilteredLucene41Postings), n_tf1=PostingsFormat(name=TestBloomFilteredLucene41Postings), n_dt1=PostingsFormat(name=SimpleText), genre_s=PostingsFormat(name=Memory doPackFST= true), author_t=PostingsFormat(name=SimpleText), range_facet_l=PostingsFormat(name=TestBloomFilteredLucene41Postings), n_ti1=PostingsFormat(name=Memory doPackFST= true), text=PostingsFormat(name=Asserting), _version_=PostingsFormat(name=SimpleText), val_i=PostingsFormat(name=Memory doPackFST= true), SubjectTerms_mfacet=PostingsFormat(name=SimpleText), series_t=PostingsFormat(name=SimpleText), a_t=PostingsFormat(name=TestBloomFilteredLucene41Postings), n_tdt1=PostingsFormat(name=SimpleText), regex_dup_A_s=PostingsFormat(name=Asserting), price=PostingsFormat(name=Asserting), other_tl1=PostingsFormat(name=SimpleText), n_l1=PostingsFormat(name=TestBloomFilteredLucene41Postings), a_si=PostingsFormat(name=SimpleText), inStock=PostingsFormat(name=Asserting)}, docValues:{timestamp=DocValuesFormat(name=CheapBastard)}, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=es_CO, timezone=America/Bahia
> [junit4:junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=2,free=180932536,total=536870912
> [junit4:junit4]   2> NOTE: All tests run in this JVM: [TestBadConfig, TestPseudoReturnFields, TestIBSimilarityFactory, TestReplicationHandler, DocValuesTest, FileBasedSpellCheckerTest, BasicHdfsTest, PrimUtilsTest, TestPHPSerializedResponseWriter, TestLRUCache, SOLR749Test, ParsingFieldUpdateProcessorsTest, TestAddFieldRealTimeGet, DistributedTermsComponentTest, TestMaxScoreQueryParser, LoggingHandlerTest, ResourceLoaderTest, TestStressVersions, MinimalSchemaTest, TestDefaultSearchFieldResource, RegexBoostProcessorTest, TestFunctionQuery, PolyFieldTest, TestSolrDeletionPolicy1, ShowFileRequestHandlerTest, TestCopyFieldCollectionResource, TestQueryUtils, TestLFUCache, PrimitiveFieldTypeTest, TestTrie, TestSearchPerf, SuggesterTest, QueryEqualityTest, UpdateRequestProcessorFactoryTest, MBeansHandlerTest, BlockDirectoryTest, SolrIndexSplitterTest, SyncSliceTest, BadCopyFieldTest, DirectUpdateHandlerOptimizeTest, SynonymTokenizerTest, TestManagedSchemaFieldResource, SuggesterFSTTest, PeerSyncTest, TestSolrDeletionPolicy2, TestGroupingSearch, TestDynamicFieldCollectionResource, AutoCommitTest, TestRandomDVFaceting, ShardRoutingTest, OverseerCollectionProcessorTest, TestFieldResource, DistributedSpellCheckComponentTest, TestSolrIndexConfig, CSVRequestHandlerTest, FieldMutatingUpdateProcessorTest, SimpleFacetsTest, TestXIncludeConfig, TestJoin, TestStressRecovery, TestWriterPerf, BasicDistributedZkTest]
> [junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=BasicDistributedZkTest -Dtests.seed=61B7523138BE4F06 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_CO -Dtests.timezone=America/Bahia -Dtests.file.encoding=ISO-8859-1
> [junit4:junit4] ERROR   0.00s J0 | 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=2538, name=recoveryCmdExecutor-1003-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
> [junit4:junit4]    >         at java.net.PlainSocketImpl.socketConnect(Native Method)
> [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.SocksSocketImpl.connect(SocksSocketImpl.java:391)
> [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:722)
> [junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([61B7523138BE4F06]:0)Throwable #2: com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
> [junit4:junit4]    >    1) Thread[id=2538, name=recoveryCmdExecutor-1003-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
> [junit4:junit4]    >         at java.net.PlainSocketImpl.socketConnect(Native Method)
> [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.SocksSocketImpl.connect(SocksSocketImpl.java:391)
> [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:722)
> [junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([61B7523138BE4F06]:0)
> [junit4:junit4] Completed on J0 in 242.77s, 1 test, 2 errors <<< FAILURES!
> 
> [...truncated 533 lines...]
> BUILD FAILED
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:386: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:366: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:39: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build.xml:190: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/common-build.xml:443: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:1245: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:889: There were test failures: 312 suites, 1316 tests, 2 suite-level errors, 628 ignored (5 assumptions)
> 
> Total time: 40 minutes 55 seconds
> Build step 'Invoke Ant' marked build as failure
> Archiving artifacts
> Recording test results
> Email was triggered for: Failure
> Sending email for trigger: Failure
> 
> 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> For additional commands, e-mail: dev-help@lucene.apache.org


---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org


Mime
View raw message