lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Apache Jenkins Server <jenk...@builds.apache.org>
Subject [JENKINS] Lucene-Solr-Tests-trunk-Java7 - Build # 4101 - Still Failing
Date Mon, 01 Jul 2013 00:44:43 GMT
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java7/4101/

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=997, name=recoveryCmdExecutor-166-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=997, name=recoveryCmdExecutor-166-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([9340903FD7C7D6D8]: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=997, name=recoveryCmdExecutor-166-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=997, name=recoveryCmdExecutor-166-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([9340903FD7C7D6D8]:0)




Build Log:
[...truncated 9181 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest
[junit4:junit4]   2> 94969 T521 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 94975 T521 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-1372638152823
[junit4:junit4]   2> 94976 T521 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 94976 T522 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 95077 T521 oasc.ZkTestServer.run start zk server on port:24079
[junit4:junit4]   2> 95078 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 95083 T528 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7f762a9e name:ZooKeeperConnection Watcher:127.0.0.1:24079 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 95083 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 95084 T521 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 95101 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 95102 T530 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13d6e17a name:ZooKeeperConnection Watcher:127.0.0.1:24079/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 95103 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 95103 T521 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 95113 T521 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 95117 T521 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 95119 T521 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 95128 T521 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> 95129 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 95142 T521 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> 95143 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 95247 T521 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> 95248 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 95251 T521 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> 95252 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 95262 T521 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> 95263 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 95265 T521 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> 95266 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 95270 T521 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> 95270 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 95273 T521 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> 95274 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 95277 T521 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> 95278 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 96196 T521 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 96460 T521 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:24082
[junit4:junit4]   2> 96504 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 96505 T521 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 96505 T521 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-1372638153135
[junit4:junit4]   2> 96506 T521 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-1372638153135/solr.xml
[junit4:junit4]   2> 96506 T521 oasc.CoreContainer.<init> New CoreContainer 318197175
[junit4:junit4]   2> 96507 T521 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-1372638153135/'
[junit4:junit4]   2> 96507 T521 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-1372638153135/'
[junit4:junit4]   2> 96679 T521 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 96680 T521 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 96680 T521 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 96681 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 96681 T521 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 96682 T521 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 96682 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 96682 T521 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 96683 T521 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 96732 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 97215 T521 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 97216 T521 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:24079/solr
[junit4:junit4]   2> 97230 T521 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 97231 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 97235 T542 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1164ad0 name:ZooKeeperConnection Watcher:127.0.0.1:24079 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 97235 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 97241 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 97255 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 97257 T544 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1fd4eeea name:ZooKeeperConnection Watcher:127.0.0.1:24079/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 97258 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 97260 T521 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 97274 T521 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 97278 T521 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 97281 T521 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:24082_
[junit4:junit4]   2> 97289 T521 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:24082_
[junit4:junit4]   2> 97293 T521 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 97305 T521 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 97315 T521 oasc.Overseer.start Overseer (id=89957213983866883-127.0.0.1:24082_-n_0000000000) starting
[junit4:junit4]   2> 97327 T521 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 97330 T546 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 97331 T521 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 97334 T521 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 97340 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 97342 T545 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 97383 T547 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 97383 T547 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 97385 T547 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4]   2> 98846 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 98847 T545 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:24082_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:24082"}
[junit4:junit4]   2> 98847 T545 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 98847 T545 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 98868 T544 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> 99387 T547 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4]   2> 99387 T547 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-1372638153135/collection1
[junit4:junit4]   2> 99388 T547 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 99389 T547 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 99389 T547 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 99392 T547 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-1372638153135/collection1/'
[junit4:junit4]   2> 99394 T547 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-1372638153135/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 99395 T547 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-1372638153135/collection1/lib/README' to classloader
[junit4:junit4]   2> 99517 T547 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 99604 T547 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 99706 T547 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 99769 T547 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 100565 T547 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 100587 T547 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 100592 T547 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 100625 T547 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 100632 T547 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 100639 T547 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 100640 T547 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 100640 T547 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 100641 T547 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 100642 T547 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 100642 T547 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 100643 T547 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 100643 T547 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-1372638153135/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/control/data/
[junit4:junit4]   2> 100644 T547 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e91824
[junit4:junit4]   2> 100646 T547 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/control/data
[junit4:junit4]   2> 100647 T547 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/control/data/index/
[junit4:junit4]   2> 100647 T547 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 100648 T547 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/control/data/index
[junit4:junit4]   2> 100654 T547 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67fff2dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@69b18bd8),segFN=segments_1,generation=1}
[junit4:junit4]   2> 100654 T547 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 100659 T547 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 100659 T547 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 100661 T547 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 100662 T547 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 100663 T547 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 100663 T547 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 100664 T547 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 100665 T547 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 100666 T547 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 100683 T547 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 100692 T547 oass.SolrIndexSearcher.<init> Opening Searcher@28031121 main
[junit4:junit4]   2> 100694 T547 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 100694 T547 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 100702 T548 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@28031121 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 100707 T547 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 100707 T547 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:24082 collection:control_collection shard:shard1
[junit4:junit4]   2> 100719 T547 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4]   2> 100745 T547 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 100765 T547 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4]   2> 100768 T547 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 100768 T547 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 100769 T547 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:24082/collection1/
[junit4:junit4]   2> 100769 T547 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 100770 T547 oasc.SyncStrategy.syncToMe http://127.0.0.1:24082/collection1/ has no replicas
[junit4:junit4]   2> 100770 T547 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:24082/collection1/ shard1
[junit4:junit4]   2> 100771 T547 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 101874 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 101923 T544 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> 101958 T547 oasc.ZkController.register We are http://127.0.0.1:24082/collection1/ and leader is http://127.0.0.1:24082/collection1/
[junit4:junit4]   2> 101958 T547 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:24082
[junit4:junit4]   2> 101959 T547 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 101959 T547 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 101959 T547 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 101961 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 101968 T521 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> 101969 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 102069 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 102098 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 102106 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 102113 T551 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@34ed0665 name:ZooKeeperConnection Watcher:127.0.0.1:24079/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 102113 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 102114 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 102119 T521 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 102391 T521 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 102394 T521 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:24086
[junit4:junit4]   2> 102395 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 102396 T521 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 102396 T521 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-1372638159967
[junit4:junit4]   2> 102397 T521 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-1372638159967/solr.xml
[junit4:junit4]   2> 102398 T521 oasc.CoreContainer.<init> New CoreContainer 1681937453
[junit4:junit4]   2> 102398 T521 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-1372638159967/'
[junit4:junit4]   2> 102399 T521 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-1372638159967/'
[junit4:junit4]   2> 102550 T521 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 102551 T521 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 102552 T521 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 102552 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 102553 T521 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 102553 T521 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 102554 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 102555 T521 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 102555 T521 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 102556 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 102576 T521 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 102577 T521 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:24079/solr
[junit4:junit4]   2> 102577 T521 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 102578 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 102581 T562 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f751b15 name:ZooKeeperConnection Watcher:127.0.0.1:24079 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 102582 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 102599 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 102614 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 102616 T564 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14581b64 name:ZooKeeperConnection Watcher:127.0.0.1:24079/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 102617 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 102626 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 103434 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 103436 T545 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:24082_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:24082"}
[junit4:junit4]   2> 103452 T564 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> 103452 T551 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> 103452 T544 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> 103630 T521 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:24086_
[junit4:junit4]   2> 103632 T521 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:24086_
[junit4:junit4]   2> 103635 T564 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> 103635 T551 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> 103635 T544 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 103636 T544 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> 103636 T564 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 103644 T551 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 103651 T565 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 103651 T565 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 103653 T565 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4]   2> 104956 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 104957 T545 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:24086_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:24086"}
[junit4:junit4]   2> 104958 T545 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 104958 T545 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 104977 T564 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> 104977 T551 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> 104977 T544 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> 105655 T565 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4]   2> 105655 T565 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-1372638159967/collection1
[junit4:junit4]   2> 105656 T565 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 105656 T565 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 105657 T565 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 105659 T565 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-1372638159967/collection1/'
[junit4:junit4]   2> 105660 T565 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-1372638159967/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 105661 T565 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-1372638159967/collection1/lib/README' to classloader
[junit4:junit4]   2> 105741 T565 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 105823 T565 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 105924 T565 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 105966 T565 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 106739 T565 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 106763 T565 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 106768 T565 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 106798 T565 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 106804 T565 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 106810 T565 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 106812 T565 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 106812 T565 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 106813 T565 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 106814 T565 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 106814 T565 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 106815 T565 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 106815 T565 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-1372638159967/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty1/
[junit4:junit4]   2> 106816 T565 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e91824
[junit4:junit4]   2> 106818 T565 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty1
[junit4:junit4]   2> 106818 T565 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty1/index/
[junit4:junit4]   2> 106819 T565 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 106819 T565 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty1/index
[junit4:junit4]   2> 106824 T565 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_1,generation=1}
[junit4:junit4]   2> 106824 T565 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 106829 T565 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 106830 T565 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 106831 T565 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 106833 T565 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 106834 T565 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 106834 T565 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 106835 T565 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 106836 T565 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 106837 T565 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 106854 T565 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 106863 T565 oass.SolrIndexSearcher.<init> Opening Searcher@6f23c5ef main
[junit4:junit4]   2> 106864 T565 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 106865 T565 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 106875 T566 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6f23c5ef main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 106881 T565 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 106881 T565 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:24086 collection:collection1 shard:shard1
[junit4:junit4]   2> 106882 T565 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 106935 T565 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4]   2> 106938 T565 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 106938 T565 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 106939 T565 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:24086/collection1/
[junit4:junit4]   2> 106939 T565 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 106940 T565 oasc.SyncStrategy.syncToMe http://127.0.0.1:24086/collection1/ has no replicas
[junit4:junit4]   2> 106940 T565 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:24086/collection1/ shard1
[junit4:junit4]   2> 106940 T565 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 107983 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 108003 T564 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> 108003 T551 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> 108003 T544 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> 108017 T565 oasc.ZkController.register We are http://127.0.0.1:24086/collection1/ and leader is http://127.0.0.1:24086/collection1/
[junit4:junit4]   2> 108017 T565 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:24086
[junit4:junit4]   2> 108017 T565 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 108018 T565 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 108018 T565 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 108020 T565 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 108021 T521 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> 108022 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 108022 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 108319 T521 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 108322 T521 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:24090
[junit4:junit4]   2> 108323 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 108324 T521 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 108325 T521 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-1372638165890
[junit4:junit4]   2> 108325 T521 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-1372638165890/solr.xml
[junit4:junit4]   2> 108326 T521 oasc.CoreContainer.<init> New CoreContainer 450148949
[junit4:junit4]   2> 108327 T521 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-1372638165890/'
[junit4:junit4]   2> 108327 T521 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-1372638165890/'
[junit4:junit4]   2> 108490 T521 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 108491 T521 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 108491 T521 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 108492 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 108492 T521 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 108493 T521 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 108493 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 108494 T521 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 108495 T521 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 108495 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 108515 T521 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 108516 T521 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:24079/solr
[junit4:junit4]   2> 108516 T521 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 108517 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 108521 T578 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7c0e8d95 name:ZooKeeperConnection Watcher:127.0.0.1:24079 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 108522 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 108536 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 108551 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 108553 T580 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2c160110 name:ZooKeeperConnection Watcher:127.0.0.1:24079/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 108553 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 108564 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 109508 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 109509 T545 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:24086_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:24086"}
[junit4:junit4]   2> 109525 T580 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> 109525 T551 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> 109525 T564 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> 109525 T544 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> 109568 T521 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:24090_
[junit4:junit4]   2> 109570 T521 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:24090_
[junit4:junit4]   2> 109573 T564 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> 109573 T551 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> 109573 T580 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> 109573 T544 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 109574 T544 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> 109575 T564 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 109575 T551 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 109576 T580 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 109582 T581 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 109582 T581 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 109584 T581 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4]   2> 111029 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 111030 T545 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:24090_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:24090"}
[junit4:junit4]   2> 111031 T545 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 111031 T545 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 111036 T564 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> 111036 T551 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> 111036 T580 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> 111036 T544 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> 111586 T581 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4]   2> 111586 T581 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-1372638165890/collection1
[junit4:junit4]   2> 111587 T581 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 111587 T581 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 111588 T581 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 111590 T581 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-1372638165890/collection1/'
[junit4:junit4]   2> 111591 T581 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-1372638165890/collection1/lib/README' to classloader
[junit4:junit4]   2> 111592 T581 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-1372638165890/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 111661 T581 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 111736 T581 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 111838 T581 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 111874 T581 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 112628 T581 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 112649 T581 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 112654 T581 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 112685 T581 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 112691 T581 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 112697 T581 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 112698 T581 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 112699 T581 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 112700 T581 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 112701 T581 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 112701 T581 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 112702 T581 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 112702 T581 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-1372638165890/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty2/
[junit4:junit4]   2> 112702 T581 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e91824
[junit4:junit4]   2> 112704 T581 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty2
[junit4:junit4]   2> 112704 T581 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty2/index/
[junit4:junit4]   2> 112705 T581 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 112705 T581 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty2/index
[junit4:junit4]   2> 112711 T581 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6d217978 lockFactory=org.apache.lucene.store.NativeFSLockFactory@263a4b0c),segFN=segments_1,generation=1}
[junit4:junit4]   2> 112711 T581 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 112716 T581 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 112717 T581 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 112718 T581 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 112719 T581 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 112720 T581 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 112721 T581 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 112721 T581 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 112723 T581 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 112724 T581 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 112740 T581 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 112748 T581 oass.SolrIndexSearcher.<init> Opening Searcher@652eaec main
[junit4:junit4]   2> 112750 T581 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 112750 T581 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 112761 T582 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@652eaec main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 112767 T581 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 112767 T581 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:24090 collection:collection1 shard:shard2
[junit4:junit4]   2> 112768 T581 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 112790 T581 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
[junit4:junit4]   2> 112801 T581 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 112801 T581 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 112802 T581 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:24090/collection1/
[junit4:junit4]   2> 112802 T581 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 112802 T581 oasc.SyncStrategy.syncToMe http://127.0.0.1:24090/collection1/ has no replicas
[junit4:junit4]   2> 112803 T581 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:24090/collection1/ shard2
[junit4:junit4]   2> 112803 T581 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 114052 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 114074 T544 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> 114074 T551 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> 114074 T580 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> 114074 T564 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> 114093 T581 oasc.ZkController.register We are http://127.0.0.1:24090/collection1/ and leader is http://127.0.0.1:24090/collection1/
[junit4:junit4]   2> 114093 T581 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:24090
[junit4:junit4]   2> 114093 T581 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 114094 T581 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 114094 T581 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 114096 T581 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 114097 T521 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> 114098 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 114098 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 114388 T521 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 114391 T521 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:21017
[junit4:junit4]   2> 114392 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 114393 T521 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 114394 T521 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-1372638171965
[junit4:junit4]   2> 114394 T521 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-1372638171965/solr.xml
[junit4:junit4]   2> 114395 T521 oasc.CoreContainer.<init> New CoreContainer 1496973014
[junit4:junit4]   2> 114396 T521 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-1372638171965/'
[junit4:junit4]   2> 114396 T521 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-1372638171965/'
[junit4:junit4]   2> 114543 T521 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 114544 T521 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 114544 T521 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 114545 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 114545 T521 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 114546 T521 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 114546 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 114547 T521 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 114548 T521 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 114548 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 114568 T521 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 114569 T521 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:24079/solr
[junit4:junit4]   2> 114569 T521 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 114570 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 114573 T594 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6c9532e1 name:ZooKeeperConnection Watcher:127.0.0.1:24079 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 114574 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 114577 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 114591 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 114594 T596 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28c61629 name:ZooKeeperConnection Watcher:127.0.0.1:24079/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 114594 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 114606 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 115580 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 115581 T545 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:24090_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:24090"}
[junit4:junit4]   2> 115602 T596 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> 115602 T551 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> 115602 T580 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> 115602 T544 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> 115602 T564 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> 115610 T521 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:21017_
[junit4:junit4]   2> 115612 T521 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:21017_
[junit4:junit4]   2> 115614 T564 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> 115615 T580 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> 115615 T544 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 115615 T551 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> 115616 T544 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> 115616 T564 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 115615 T596 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 115617 T596 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> 115623 T580 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 115624 T551 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 115630 T597 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 115630 T597 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 115632 T597 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4]   2> 117107 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 117108 T545 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:21017_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:21017"}
[junit4:junit4]   2> 117109 T545 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 117109 T545 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 117116 T564 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> 117116 T544 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> 117116 T551 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> 117116 T580 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> 117116 T596 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> 117635 T597 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4]   2> 117635 T597 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-1372638171965/collection1
[junit4:junit4]   2> 117636 T597 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 117636 T597 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 117637 T597 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 117639 T597 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-1372638171965/collection1/'
[junit4:junit4]   2> 117640 T597 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-1372638171965/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 117641 T597 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-1372638171965/collection1/lib/README' to classloader
[junit4:junit4]   2> 117705 T597 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 117787 T597 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 117889 T597 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 117921 T597 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 118651 T597 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 118669 T597 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 118673 T597 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 118701 T597 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 118708 T597 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 118713 T597 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 118714 T597 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 118715 T597 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 118716 T597 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 118717 T597 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 118717 T597 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 118717 T597 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 118718 T597 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-1372638171965/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty3/
[junit4:junit4]   2> 118718 T597 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e91824
[junit4:junit4]   2> 118720 T597 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty3
[junit4:junit4]   2> 118720 T597 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty3/index/
[junit4:junit4]   2> 118720 T597 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 118721 T597 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty3/index
[junit4:junit4]   2> 118725 T597 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a25a4d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a32e49c),segFN=segments_1,generation=1}
[junit4:junit4]   2> 118726 T597 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 118730 T597 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 118731 T597 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 118732 T597 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 118733 T597 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 118734 T597 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 118735 T597 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 118735 T597 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 118736 T597 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 118737 T597 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 118752 T597 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 118760 T597 oass.SolrIndexSearcher.<init> Opening Searcher@3a6e99c1 main
[junit4:junit4]   2> 118761 T597 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 118762 T597 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 118772 T598 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3a6e99c1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 118778 T597 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 118778 T597 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:21017 collection:collection1 shard:shard1
[junit4:junit4]   2> 118782 T597 oasc.ZkController.register We are http://127.0.0.1:21017/collection1/ and leader is http://127.0.0.1:24086/collection1/
[junit4:junit4]   2> 118782 T597 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:21017
[junit4:junit4]   2> 118782 T597 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 118783 T597 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C2 name=collection1 org.apache.solr.core.SolrCore@9346193 url=http://127.0.0.1:21017/collection1 node=127.0.0.1:21017_ C2_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:21017_, base_url=http://127.0.0.1:21017}
[junit4:junit4]   2> 118790 T599 C2 P21017 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 118790 T597 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 118791 T599 C2 P21017 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 118791 T599 C2 P21017 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 118792 T599 C2 P21017 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 118792 T521 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> 118793 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 118793 T599 C2 P21017 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 118793 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 119165 T521 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 119169 T521 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:44764
[junit4:junit4]   2> 119170 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 119170 T521 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 119171 T521 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-1372638176665
[junit4:junit4]   2> 119171 T521 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-1372638176665/solr.xml
[junit4:junit4]   2> 119172 T521 oasc.CoreContainer.<init> New CoreContainer 341679870
[junit4:junit4]   2> 119173 T521 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-1372638176665/'
[junit4:junit4]   2> 119173 T521 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-1372638176665/'
[junit4:junit4]   2> 119363 T521 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 119364 T521 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 119364 T521 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 119365 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 119365 T521 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 119366 T521 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 119366 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 119367 T521 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 119367 T521 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 119368 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 119391 T521 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 119391 T521 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:24079/solr
[junit4:junit4]   2> 119392 T521 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 119393 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 119396 T611 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@46a2ca3e name:ZooKeeperConnection Watcher:127.0.0.1:24079 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 119397 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 119414 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 119431 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 119435 T613 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@62f5ae30 name:ZooKeeperConnection Watcher:127.0.0.1:24079/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 119435 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 119448 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 120124 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 120125 T545 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:21017_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:21017"}
[junit4:junit4]   2> 120146 T596 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> 120146 T613 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> 120146 T544 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> 120146 T580 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> 120146 T564 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> 120146 T551 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> 120387 T554 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 120388 T554 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true for: 0 seconds.
[junit4:junit4]   2> 120389 T554 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node3&state=recovering&nodeName=127.0.0.1:21017_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=8 
[junit4:junit4]   2> 120451 T521 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44764_
[junit4:junit4]   2> 120453 T521 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44764_
[junit4:junit4]   2> 120455 T613 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> 120456 T596 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 120456 T596 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> 120455 T551 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> 120455 T564 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> 120455 T580 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> 120456 T544 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 120459 T544 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> 120465 T613 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 120466 T580 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 120466 T564 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 120466 T551 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 120480 T614 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 120480 T614 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 120482 T614 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4]   2> 121650 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 121652 T545 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:44764_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:44764"}
[junit4:junit4]   2> 121653 T545 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 121654 T545 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 121689 T564 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> 121689 T551 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> 121689 T544 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> 121689 T580 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> 121689 T613 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> 121689 T596 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> 122485 T614 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4]   2> 122486 T614 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-1372638176665/collection1
[junit4:junit4]   2> 122487 T614 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 122488 T614 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 122488 T614 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 122490 T614 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-1372638176665/collection1/'
[junit4:junit4]   2> 122492 T614 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-1372638176665/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 122494 T614 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-1372638176665/collection1/lib/README' to classloader
[junit4:junit4]   2> ASYNC  NEW_CORE C3 name=collection1 org.apache.solr.core.SolrCore@9346193 url=http://127.0.0.1:21017/collection1 node=127.0.0.1:21017_ C3_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:21017_, base_url=http://127.0.0.1:21017}
[junit4:junit4]   2> 122568 T599 C3 P21017 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:24086/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 122582 T599 C3 P21017 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4]   2> 122613 T599 C3 P21017 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:21017 START replicas=[http://127.0.0.1:24086/collection1/] nUpdates=100
[junit4:junit4]   2> 122613 T614 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 122629 T599 C3 P21017 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 122630 T599 C3 P21017 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 122630 T599 C3 P21017 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 122630 T599 C3 P21017 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 122631 T599 C3 P21017 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 122631 T599 C3 P21017 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:24086/collection1/. core=collection1
[junit4:junit4]   2> 122632 T599 C3 P21017 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C4 name=collection1 org.apache.solr.core.SolrCore@3c41d377 url=http://127.0.0.1:24086/collection1 node=127.0.0.1:24086_ C4_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:24086_, base_url=http://127.0.0.1:24086, leader=true}
[junit4:junit4]   2> 122690 T555 C4 P24086 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=9 
[junit4:junit4]   2> 122712 T614 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 122731 T556 C4 P24086 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 122736 T556 C4 P24086 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_1,generation=1}
[junit4:junit4]   2> 122737 T556 C4 P24086 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 122737 T556 C4 P24086 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 122738 T556 C4 P24086 oass.SolrIndexSearcher.<init> Opening Searcher@42a70f8c realtime
[junit4:junit4]   2> 122739 T556 C4 P24086 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 122739 T556 C4 P24086 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 58
[junit4:junit4]   2> 122813 T614 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 122818 T599 C3 P21017 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 122818 T599 C3 P21017 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4]   2> 122848 T599 C3 P21017 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 122854 T614 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> ASYNC  NEW_CORE C5 name=collection1 org.apache.solr.core.SolrCore@3c41d377 url=http://127.0.0.1:24086/collection1 node=127.0.0.1:24086_ C5_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:24086_, base_url=http://127.0.0.1:24086, leader=true}
[junit4:junit4]   2> 122945 T557 C5 P24086 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 122946 T557 C5 P24086 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=94 
[junit4:junit4]   2> ASYNC  NEW_CORE C6 name=collection1 org.apache.solr.core.SolrCore@9346193 url=http://127.0.0.1:21017/collection1 node=127.0.0.1:21017_ C6_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:21017_, base_url=http://127.0.0.1:21017}
[junit4:junit4]   2> 122948 T599 C6 P21017 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 122948 T599 C6 P21017 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 122949 T599 C6 P21017 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 122949 T599 C6 P21017 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 122957 T599 C6 P21017 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 123194 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 123196 T545 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:21017_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:21017"}
[junit4:junit4]   2> 123223 T613 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> 123223 T564 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> 123223 T580 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> 123223 T551 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> 123223 T596 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> 123223 T544 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> 123702 T614 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 123721 T614 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 123726 T614 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 123757 T614 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 123763 T614 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 123769 T614 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 123771 T614 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 123771 T614 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 123772 T614 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 123773 T614 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 123773 T614 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 123774 T614 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 123774 T614 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-1372638176665/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty4/
[junit4:junit4]   2> 123774 T614 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e91824
[junit4:junit4]   2> 123776 T614 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty4
[junit4:junit4]   2> 123776 T614 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty4/index/
[junit4:junit4]   2> 123777 T614 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 123777 T614 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372638152822/jetty4/index
[junit4:junit4]   2> 123782 T614 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@74510dba lockFactory=org.apache.lucene.store.NativeFSLockFactory@75c74de9),segFN=segments_1,generation=1}
[junit4:junit4]   2> 123782 T614 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 123787 T614 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 123788 T614 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 123789 T614 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 123791 T614 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 123792 T614 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 123793 T614 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 123800 T614 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 123802 T614 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 123802 T614 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 123819 T614 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 123828 T614 oass.SolrIndexSearcher.<init> Opening Searcher@e9fe846 main
[junit4:junit4]   2> 123829 T614 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 123830 T614 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 123842 T616 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e9fe846 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 123847 T614 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 123848 T614 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44764 collection:collection1 shard:shard2
[junit4:junit4]   2> 123851 T614 oasc.ZkController.register We are http://127.0.0.1:44764/collection1/ and leader is http://127.0.0.1:24090/collection1/
[junit4:junit4]   2> 123852 T614 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44764
[junit4:junit4]   2> 123852 T614 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 123852 T614 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C7 name=collection1 org.apache.solr.core.SolrCore@182275f2 url=http://127.0.0.1:44764/collection1 node=127.0.0.1:44764_ C7_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:44764_, base_url=http://127.0.0.1:44764}
[junit4:junit4]   2> 123853 T617 C7 P44764 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 123854 T614 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 123854 T617 C7 P44764 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 123855 T617 C7 P44764 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 123855 T617 C7 P44764 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 123855 T521 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> 123856 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 123857 T617 C7 P44764 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 123857 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 123878 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 123881 T570 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 123881 T521 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):330
[junit4:junit4]   2> 123883 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 124727 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 124728 T545 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:44764_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:44764"}
[junit4:junit4]   2> 124749 T596 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> 124750 T580 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> 124750 T551 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> 124749 T613 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> 124749 T544 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> 124749 T564 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> 124883 T570 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4]   2> 124883 T570 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node4&state=recovering&nodeName=127.0.0.1:44764_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002 
[junit4:junit4]   2> 124885 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 125887 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C7_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:44764_, base_url=http://127.0.0.1:44764}
[junit4:junit4]   2> 126885 T617 C7 P44764 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:24090/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 126885 T617 C7 P44764 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:44764 START replicas=[http://127.0.0.1:24090/collection1/] nUpdates=100
[junit4:junit4]   2> 126887 T617 C7 P44764 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 126887 T617 C7 P44764 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 126887 T617 C7 P44764 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 126887 T617 C7 P44764 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 126888 T617 C7 P44764 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 126889 T617 C7 P44764 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:24090/collection1/. core=collection1
[junit4:junit4]   2> 126889 T617 C7 P44764 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 126890 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> ASYNC  NEW_CORE C8 name=collection1 org.apache.solr.core.SolrCore@6d20036b url=http://127.0.0.1:24090/collection1 node=127.0.0.1:24090_ C8_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:24090_, base_url=http://127.0.0.1:24090, leader=true}
[junit4:junit4]   2> 126898 T571 C8 P24090 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 126904 T572 C8 P24090 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 126908 T572 C8 P24090 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6d217978 lockFactory=org.apache.lucene.store.NativeFSLockFactory@263a4b0c),segFN=segments_1,generation=1}
[junit4:junit4]   2> 126909 T572 C8 P24090 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 126910 T572 C8 P24090 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 126910 T572 C8 P24090 oass.SolrIndexSearcher.<init> Opening Searcher@3a5cd1d3 realtime
[junit4:junit4]   2> 126911 T572 C8 P24090 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 126911 T572 C8 P24090 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4]   2> 126913 T617 C7 P44764 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 126913 T617 C7 P44764 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 126917 T573 C8 P24090 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 126918 T573 C8 P24090 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 126919 T617 C7 P44764 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 126919 T617 C7 P44764 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 126920 T617 C7 P44764 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 126920 T617 C7 P44764 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 126922 T617 C7 P44764 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 127756 T545 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 127757 T545 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:44764_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:44764"}
[junit4:junit4]   2> 127777 T564 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> 127777 T544 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> 127777 T596 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> 127777 T613 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> 127777 T551 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> 127777 T580 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> 127892 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 127893 T521 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4]   2> ASYNC  NEW_CORE C9 name=collection1 org.apache.solr.core.SolrCore@5dd15fc4 url=http://127.0.0.1:24082/collection1 node=127.0.0.1:24082_ C9_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:24082_, base_url=http://127.0.0.1:24082, leader=true}
[junit4:junit4]   2> 128081 T533 C9 P24082 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67fff2dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@69b18bd8),segFN=segments_1,generation=1}
[junit4:junit4]   2> 128082 T533 C9 P24082 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 128132 T533 C9 P24082 oass.SolrIndexSearcher.<init> Opening Searcher@581f9a8c realtime
[junit4:junit4]   2> 128138 T533 C9 P24082 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439315458386821120)} 0 151
[junit4:junit4]   2>  C7_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:44764_, base_url=http://127.0.0.1:44764}
[junit4:junit4]   2> 128210 T604 C7 P44764 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@74510dba lockFactory=org.apache.lucene.store.NativeFSLockFactory@75c74de9),segFN=segments_1,generation=1}
[junit4:junit4]   2> 128211 T604 C7 P44764 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 128213 T604 C7 P44764 oass.SolrIndexSearcher.<init> Opening Searcher@3ddf06fd realtime
[junit4:junit4]   2> 128214 T604 C7 P44764 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1439315458570321920&update.from=http://127.0.0.1:24090/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439315458570321920)} 0 8
[junit4:junit4]   2> 128215 T574 C8 P24090 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1439315458570321920)} 0 18
[junit4:junit4]   2> ASYNC  NEW_CORE C10 name=collection1 org.apache.solr.core.SolrCore@9346193 url=http://127.0.0.1:21017/collection1 node=127.0.0.1:21017_ C10_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:21017_, base_url=http://127.0.0.1:21017}
[junit4:junit4]   2> 128218 T586 C10 P21017 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a25a4d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a32e49c),segFN=segments_1,generation=1}
[junit4:junit4]   2> 128219 T586 C10 P21017 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 128221 T586 C10 P21017 oass.SolrIndexSearcher.<init> Opening Searcher@22d9628f realtime
[junit4:junit4]   2> 128221 T586 C10 P21017 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1439315458570321920&update.from=http://127.0.0.1:24086/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439315458570321920)} 0 6
[junit4:junit4]   2> ASYNC  NEW_CORE C11 name=collection1 org.apache.solr.core.SolrCore@3c41d377 url=http://127.0.0.1:24086/collection1 node=127.0.0.1:24086_ C11_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:24086_, base_url=http://127.0.0.1:24086, leader=true}
[junit4:junit4]   2> 128222 T558 C11 P24086 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1439315458570321920)} 0 25
[junit4:junit4]   2> 128224 T603 C7 P44764 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 45
[junit4:junit4]   2> 128225 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 128227 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 128238 T559 C11 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=7 
[junit4:junit4]   2> 128243 T587 C10 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=1 
[junit4:junit4]   2> 128244 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 128248 T575 C8 P24090 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=0 
[junit4:junit4]   2> 128252 T605 C7 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=1 
[junit4:junit4]   2> 128268 T533 C9 P24082 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 128327 T533 C9 P24082 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67fff2dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@69b18bd8),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67fff2dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@69b18bd8),segFN=segments_2,generation=2}
[junit4:junit4]   2> 128328 T533 C9 P24082 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 128471 T533 C9 P24082 oass.SolrIndexSearcher.<init> Opening Searcher@1ecd4f54 main
[junit4:junit4]   2> 128473 T533 C9 P24082 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 128475 T548 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ecd4f54 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
[junit4:junit4]   2> 128476 T533 C9 P24082 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439315458639527936)],commit=} 0 219
[junit4:junit4]   2> 128506 T586 C10 P21017 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24086/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439315458867068928)]} 0 4
[junit4:junit4]   2> 128508 T559 C11 P24086 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:24086/collection1/, StdNode: http://127.0.0.1:21017/collection1/, StdNode: http://127.0.0.1:24090/collection1/, StdNode: http://127.0.0.1:44764/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4]   2> 128514 T560 C11 P24086 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 128514 T576 C8 P24090 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 128514 T606 C7 P44764 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 128514 T586 C10 P21017 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 128517 T606 C7 P44764 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 128516 T576 C8 P24090 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 128518 T606 C7 P44764 oass.SolrIndexSearcher.<init> Opening Searcher@44831670 main
[junit4:junit4]   2> 128519 T576 C8 P24090 oass.SolrIndexSearcher.<init> Opening Searcher@579128ce main
[junit4:junit4]   2> 128520 T606 C7 P44764 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 128522 T576 C8 P24090 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 128522 T582 oasc.JmxMonitoredMap.put WARN Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4]   2> 	at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4]   2> 	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4]   2> 	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4]   2> 	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4]   2> 	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4]   2> 	at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:513)
[junit4:junit4]   2> 	at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4]   2> 	at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4]   2> 	at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:305)
[junit4:junit4]   2> 	at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1844)
[junit4:junit4]   2> 	at org.apache.solr.core.SolrCore.access$000(SolrCore.java:135)
[junit4:junit4]   2> 	at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1721)
[junit4:junit4]   2> 	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4]   2> 	at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4]   2> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4]   2> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 128523 T616 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@44831670 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 128525 T582 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@579128ce main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 128525 T606 C7 P44764 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 128526 T576 C8 P24090 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 128529 T560 C11 P24086 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_2,generation=2}
[junit4:junit4]   2> 128529 T560 C11 P24086 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 128530 T586 C10 P21017 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a25a4d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a32e49c),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a25a4d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a32e49c),segFN=segments_2,generation=2}
[junit4:junit4]   2> 128531 T586 C10 P21017 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 128533 T560 C11 P24086 oass.SolrIndexSearcher.<init> Opening Searcher@2d62624e main
[junit4:junit4]   2> 128534 T560 C11 P24086 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 128535 T586 C10 P21017 oass.SolrIndexSearcher.<init> Opening Searcher@2e7c73e6 main
[junit4:junit4]   2> 128536 T566 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d62624e main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
[junit4:junit4]   2> 128536 T586 C10 P21017 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 128537 T560 C11 P24086 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 23
[junit4:junit4]   2> 128537 T598 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2e7c73e6 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
[junit4:junit4]   2> 128538 T586 C10 P21017 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4]   2> 128540 T559 C11 P24086 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439315458867068928)],commit=} 0 59
[junit4:junit4]   2> 128541 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 128543 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 128580 T559 C11 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=33 
[junit4:junit4]   2> 128593 T587 C10 P21017 oasc.SolrCore.execute [collection1] webapp= 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> 128601 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 128606 T575 C8 P24090 oasc.SolrCore.execute [collection1] webapp= 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> 128611 T605 C7 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=1 
[junit4:junit4]   2> 128612 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 128614 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 128701 T607 C7 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186466&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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=77 
[junit4:junit4]   2> 128701 T588 C10 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186466&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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=77 
[junit4:junit4]   2> 128740 T588 C10 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186466&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=1 
[junit4:junit4]   2> 128741 T559 C11 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=122 
[junit4:junit4]   2> 128752 T608 C7 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186593&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 128752 T589 C10 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186593&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 128757 T589 C10 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186593&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 128759 T587 C10 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=13 
[junit4:junit4]   2> 128761 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 128772 T609 C7 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186613&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 128772 T590 C10 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186613&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 128777 T590 C10 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186613&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 128779 T575 C8 P24090 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=13 
[junit4:junit4]   2> 128789 T591 C10 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186630&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 128789 T635 C7 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186630&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 128794 T591 C10 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186630&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 128796 T605 C7 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=13 
[junit4:junit4]   2> 128806 T533 C9 P24082 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 128863 T533 C9 P24082 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67fff2dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@69b18bd8),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67fff2dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@69b18bd8),segFN=segments_3,generation=3}
[junit4:junit4]   2> 128864 T533 C9 P24082 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 128867 T533 C9 P24082 oass.SolrIndexSearcher.<init> Opening Searcher@c10417 main
[junit4:junit4]   2> ASYNC  NEW_CORE C12 name=collection1 org.apache.solr.core.SolrCore@5dd15fc4 url=http://127.0.0.1:24082/collection1 node=127.0.0.1:24082_ C12_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:24082_, base_url=http://127.0.0.1:24082, leader=true}
[junit4:junit4]   2> 128879 T533 C12 P24082 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 128880 T548 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c10417 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
[junit4:junit4]   2> 128882 T533 C12 P24082 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439315459202613248)],commit=} 0 81
[junit4:junit4]   2> ASYNC  NEW_CORE C13 name=collection1 org.apache.solr.core.SolrCore@9346193 url=http://127.0.0.1:21017/collection1 node=127.0.0.1:21017_ C13_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:21017_, base_url=http://127.0.0.1:21017}
[junit4:junit4]   2> 129050 T586 C13 P21017 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24086/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439315459304325120)]} 0 144
[junit4:junit4]   2> ASYNC  NEW_CORE C14 name=collection1 org.apache.solr.core.SolrCore@3c41d377 url=http://127.0.0.1:24086/collection1 node=127.0.0.1:24086_ C14_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:24086_, base_url=http://127.0.0.1:24086, leader=true}
[junit4:junit4]   2> 129052 T554 C14 P24086 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24090/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439315459304325120)]} 0 155
[junit4:junit4]   2> ASYNC  NEW_CORE C15 name=collection1 org.apache.solr.core.SolrCore@6d20036b url=http://127.0.0.1:24090/collection1 node=127.0.0.1:24090_ C15_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:24090_, base_url=http://127.0.0.1:24090, leader=true}
[junit4:junit4]   2> 129053 T575 C15 P24090 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:24086/collection1/, StdNode: http://127.0.0.1:21017/collection1/, StdNode: http://127.0.0.1:24090/collection1/, StdNode: http://127.0.0.1:44764/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4]   2> 129059 T592 C13 P21017 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> ASYNC  NEW_CORE C16 name=collection1 org.apache.solr.core.SolrCore@182275f2 url=http://127.0.0.1:44764/collection1 node=127.0.0.1:44764_ C16_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:44764_, base_url=http://127.0.0.1:44764}
[junit4:junit4]   2> 129060 T604 C16 P44764 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129059 T554 C14 P24086 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129059 T570 C15 P24090 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129063 T604 C16 P44764 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 129065 T570 C15 P24090 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 129065 T604 C16 P44764 oass.SolrIndexSearcher.<init> Opening Searcher@38be4062 main
[junit4:junit4]   2> 129066 T570 C15 P24090 oass.SolrIndexSearcher.<init> Opening Searcher@d8b9fac main
[junit4:junit4]   2> 129066 T604 C16 P44764 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129067 T570 C15 P24090 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129067 T582 oasc.JmxMonitoredMap.put WARN Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4]   2> 	at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4]   2> 	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4]   2> 	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4]   2> 	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4]   2> 	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4]   2> 	at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:513)
[junit4:junit4]   2> 	at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4]   2> 	at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4]   2> 	at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:305)
[junit4:junit4]   2> 	at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1844)
[junit4:junit4]   2> 	at org.apache.solr.core.SolrCore.access$000(SolrCore.java:135)
[junit4:junit4]   2> 	at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1721)
[junit4:junit4]   2> 	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4]   2> 	at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4]   2> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4]   2> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 129068 T616 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@38be4062 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 129070 T582 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d8b9fac main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 129070 T604 C16 P44764 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 129071 T570 C15 P24090 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 129075 T592 C13 P21017 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a25a4d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a32e49c),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a25a4d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a32e49c),segFN=segments_3,generation=3}
[junit4:junit4]   2> 129075 T592 C13 P21017 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 129076 T554 C14 P24086 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_3,generation=3}
[junit4:junit4]   2> 129076 T554 C14 P24086 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 129079 T592 C13 P21017 oass.SolrIndexSearcher.<init> Opening Searcher@2b41cdbc main
[junit4:junit4]   2> 129081 T592 C13 P21017 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129081 T554 C14 P24086 oass.SolrIndexSearcher.<init> Opening Searcher@766e5053 main
[junit4:junit4]   2> 129082 T598 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2b41cdbc main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
[junit4:junit4]   2> 129082 T554 C14 P24086 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129083 T592 C13 P21017 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4]   2> 129083 T566 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@766e5053 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):C1)}
[junit4:junit4]   2> 129085 T554 C14 P24086 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 26
[junit4:junit4]   2> 129086 T575 C15 P24090 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 199
[junit4:junit4]   2> 129087 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129089 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129095 T559 C14 P24086 oasc.SolrCore.execute [collection1] webapp= 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> 129101 T587 C13 P21017 oasc.SolrCore.execute [collection1] webapp= 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> 129103 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129109 T575 C15 P24090 oasc.SolrCore.execute [collection1] webapp= 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> 129113 T605 C16 P44764 oasc.SolrCore.execute [collection1] webapp= 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> 129115 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129116 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129125 T572 C15 P24090 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186968&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 129126 T588 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186968&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129131 T588 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186968&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129133 T559 C14 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=12 
[junit4:junit4]   2> 129141 T639 C15 P24090 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186984&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 129142 T589 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186984&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129147 T589 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638186984&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129149 T587 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=12 
[junit4:junit4]   2> 129150 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129159 T640 C15 P24090 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187002&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 129160 T590 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187002&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129165 T590 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187002&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129167 T575 C15 P24090 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=12 
[junit4:junit4]   2> 129175 T641 C15 P24090 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187018&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 129176 T591 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187018&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129181 T591 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187018&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129183 T605 C16 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=12 
[junit4:junit4]   2> 129193 T533 C12 P24082 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129202 T533 C12 P24082 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67fff2dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@69b18bd8),segFN=segments_3,generation=3}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67fff2dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@69b18bd8),segFN=segments_4,generation=4}
[junit4:junit4]   2> 129202 T533 C12 P24082 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4]   2> 129206 T533 C12 P24082 oass.SolrIndexSearcher.<init> Opening Searcher@41de3257 main
[junit4:junit4]   2> 129207 T533 C12 P24082 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129208 T548 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@41de3257 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):C1)}
[junit4:junit4]   2> 129210 T533 C12 P24082 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439315459608412160)],commit=} 0 22
[junit4:junit4]   2> 129232 T586 C13 P21017 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24086/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439315459640918016)]} 0 5
[junit4:junit4]   2> 129234 T556 C14 P24086 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:21017/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439315459640918016)]} 0 15
[junit4:junit4]   2> 129235 T587 C13 P21017 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:24086/collection1/, StdNode: http://127.0.0.1:21017/collection1/, StdNode: http://127.0.0.1:24090/collection1/, StdNode: http://127.0.0.1:44764/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4]   2> 129242 T556 C14 P24086 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129242 T647 C15 P24090 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129242 T648 C16 P44764 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129242 T646 C13 P21017 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129244 T648 C16 P44764 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 129243 T647 C15 P24090 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 129246 T648 C16 P44764 oass.SolrIndexSearcher.<init> Opening Searcher@1aaa4a39 main
[junit4:junit4]   2> 129246 T647 C15 P24090 oass.SolrIndexSearcher.<init> Opening Searcher@3f3861fb main
[junit4:junit4]   2> 129247 T648 C16 P44764 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129248 T647 C15 P24090 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129249 T616 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1aaa4a39 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 129250 T648 C16 P44764 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 129251 T582 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3f3861fb main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 129252 T556 C14 P24086 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_3,generation=3}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_4,generation=4}
[junit4:junit4]   2> 129252 T647 C15 P24090 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 129253 T646 C13 P21017 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a25a4d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a32e49c),segFN=segments_3,generation=3}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a25a4d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a32e49c),segFN=segments_4,generation=4}
[junit4:junit4]   2> 129253 T556 C14 P24086 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4]   2> 129254 T646 C13 P21017 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4]   2> 129257 T556 C14 P24086 oass.SolrIndexSearcher.<init> Opening Searcher@25fb025 main
[junit4:junit4]   2> 129258 T646 C13 P21017 oass.SolrIndexSearcher.<init> Opening Searcher@531db190 main
[junit4:junit4]   2> 129258 T556 C14 P24086 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129260 T646 C13 P21017 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129261 T566 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@25fb025 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):C1)}
[junit4:junit4]   2> 129261 T598 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@531db190 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):C1)}
[junit4:junit4]   2> 129262 T556 C14 P24086 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 20
[junit4:junit4]   2> 129264 T646 C13 P21017 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 22
[junit4:junit4]   2> 129265 T587 C13 P21017 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 51
[junit4:junit4]   2> 129266 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129268 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129274 T559 C14 P24086 oasc.SolrCore.execute [collection1] webapp= 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> 129279 T587 C13 P21017 oasc.SolrCore.execute [collection1] webapp= 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> 129281 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129286 T575 C15 P24090 oasc.SolrCore.execute [collection1] webapp= 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> 129291 T605 C16 P44764 oasc.SolrCore.execute [collection1] webapp= 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> 129293 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129294 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129304 T607 C16 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187146&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 129304 T649 C14 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187146&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129310 T649 C14 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187146&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129312 T559 C14 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=13 
[junit4:junit4]   2> 129321 T650 C14 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187163&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=2 
[junit4:junit4]   2> 129321 T608 C16 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187163&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 129326 T650 C14 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187163&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129328 T587 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=12 
[junit4:junit4]   2> 129330 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129339 T651 C14 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187181&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129339 T609 C16 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187181&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 129345 T651 C14 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187181&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=1 
[junit4:junit4]   2> 129346 T575 C15 P24090 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=12 
[junit4:junit4]   2> 129356 T652 C14 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187198&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129357 T635 C16 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187198&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 129362 T652 C14 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187198&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129364 T605 C16 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=13 
[junit4:junit4]   2> 129374 T533 C12 P24082 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129381 T533 C12 P24082 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67fff2dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@69b18bd8),segFN=segments_4,generation=4}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67fff2dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@69b18bd8),segFN=segments_5,generation=5}
[junit4:junit4]   2> 129382 T533 C12 P24082 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4]   2> 129385 T533 C12 P24082 oass.SolrIndexSearcher.<init> Opening Searcher@6063f086 main
[junit4:junit4]   2> 129386 T533 C12 P24082 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129388 T548 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6063f086 main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):C1)}
[junit4:junit4]   2> 129390 T533 C12 P24082 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439315459798204416)],commit=} 0 21
[junit4:junit4]   2> 129411 T586 C13 P21017 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24086/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439315459829661696)]} 0 5
[junit4:junit4]   2> 129413 T558 C14 P24086 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:44764/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439315459829661696)]} 0 15
[junit4:junit4]   2> 129414 T605 C16 P44764 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:24086/collection1/, StdNode: http://127.0.0.1:21017/collection1/, StdNode: http://127.0.0.1:24090/collection1/, StdNode: http://127.0.0.1:44764/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4]   2> 129418 T656 C16 P44764 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129418 T558 C14 P24086 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129419 T574 C15 P24090 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129418 T655 C13 P21017 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 129420 T574 C15 P24090 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 129418 T656 C16 P44764 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 129422 T574 C15 P24090 oass.SolrIndexSearcher.<init> Opening Searcher@4b352dda main
[junit4:junit4]   2> 129423 T656 C16 P44764 oass.SolrIndexSearcher.<init> Opening Searcher@62b1f62 main
[junit4:junit4]   2> 129423 T574 C15 P24090 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129424 T656 C16 P44764 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129426 T582 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4b352dda main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 129426 T616 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@62b1f62 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 129427 T574 C15 P24090 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 129428 T558 C14 P24086 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_4,generation=4}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@164cc9b7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6148874d),segFN=segments_5,generation=5}
[junit4:junit4]   2> 129429 T558 C14 P24086 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4]   2> 129427 T656 C16 P44764 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 129429 T655 C13 P21017 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a25a4d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a32e49c),segFN=segments_4,generation=4}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a25a4d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a32e49c),segFN=segments_5,generation=5}
[junit4:junit4]   2> 129430 T655 C13 P21017 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4]   2> 129432 T558 C14 P24086 oass.SolrIndexSearcher.<init> Opening Searcher@16364f main
[junit4:junit4]   2> 129433 T558 C14 P24086 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129433 T655 C13 P21017 oass.SolrIndexSearcher.<init> Opening Searcher@cbcb654 main
[junit4:junit4]   2> 129435 T566 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16364f main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):C1)}
[junit4:junit4]   2> 129435 T655 C13 P21017 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 129437 T558 C14 P24086 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 19
[junit4:junit4]   2> 129437 T598 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@cbcb654 main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):C1)}
[junit4:junit4]   2> 129439 T655 C13 P21017 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4]   2> 129440 T605 C16 P44764 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 46
[junit4:junit4]   2> 129441 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129443 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129449 T559 C14 P24086 oasc.SolrCore.execute [collection1] webapp= 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> 129454 T587 C13 P21017 oasc.SolrCore.execute [collection1] webapp= 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> 129457 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129463 T575 C15 P24090 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=1 
[junit4:junit4]   2> 129467 T605 C16 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=1 
[junit4:junit4]   2> 129469 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129470 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 129479 T607 C16 P44764 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187321&shard.url=127.0.0.1:24090/collection1/|127.0.0.1:44764/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> 129480 T588 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187321&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/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> 129487 T588 C13 P21017 oasc.SolrCore.execute [collection1] webapp= path=/select params={NOW=1372638187321&shard.url=127.0.0.1:24086/collection1/|127.0.0.1:21017/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=1 
[junit4:junit4]   2> 129488 T559 C14 P24086 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 statu

[...truncated too long message...]

upt leaked threads:
[junit4:junit4]   2> 	   1) Thread[id=997, name=recoveryCmdExecutor-166-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
[junit4:junit4]   2> 231740 T520 ccr.ThreadLeakControl.tryToInterruptAll SEVERE There are still zombie threads that couldn't be terminated:
[junit4:junit4]   2> 	   1) Thread[id=997, name=recoveryCmdExecutor-166-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
[junit4:junit4]   2> 	        at java.net.PlainSocketImpl.socketConnect(Native Method)
[junit4:junit4]   2> 	        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
[junit4:junit4]   2> 	        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
[junit4:junit4]   2> 	        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
[junit4:junit4]   2> 	        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:391)
[junit4:junit4]   2> 	        at java.net.Socket.connect(Socket.java:579)
[junit4:junit4]   2> 	        at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
[junit4:junit4]   2> 	        at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
[junit4:junit4]   2> 	        at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
[junit4:junit4]   2> 	        at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
[junit4:junit4]   2> 	        at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
[junit4:junit4]   2> 	        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
[junit4:junit4]   2> 	        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
[junit4:junit4]   2> 	        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
[junit4:junit4]   2> 	        at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
[junit4:junit4]   2> 	        at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4]   2> 	        at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297)
[junit4:junit4]   2> 	        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4]   2> 	        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4]   2> 	        at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> NOTE: test params are: codec=Lucene40, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=es_EC, timezone=America/Cayman
[junit4:junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=2,free=229778352,total=337641472
[junit4:junit4]   2> NOTE: All tests run in this JVM: [OverseerCollectionProcessorTest, TestXIncludeConfig, TestMaxScoreQueryParser, OverseerTest, FastVectorHighlighterTest, UpdateRequestProcessorFactoryTest, TestSolrXml, BasicDistributedZkTest]
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=BasicDistributedZkTest -Dtests.seed=9340903FD7C7D6D8 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_EC -Dtests.timezone=America/Cayman -Dtests.file.encoding=US-ASCII
[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=997, name=recoveryCmdExecutor-166-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([9340903FD7C7D6D8]:0)Throwable #2: com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
[junit4:junit4]    >    1) Thread[id=997, name=recoveryCmdExecutor-166-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([9340903FD7C7D6D8]:0)
[junit4:junit4] Completed on J0 in 231.86s, 1 test, 2 errors <<< FAILURES!

[...truncated 905 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, 930 ignored (1 assumption)

Total time: 43 minutes 54 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message