[JENKINS] Lucene-Solr-trunk-Windows (64bit/jdk1.7.0_25) - Build # 2980 - Failure!

classic Classic list List threaded Threaded
1 message Options
Reply | Threaded
Open this post in threaded view
|

[JENKINS] Lucene-Solr-trunk-Windows (64bit/jdk1.7.0_25) - Build # 2980 - Failure!

Policeman Jenkins Server-2
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/2980/
Java: 64bit/jdk1.7.0_25 -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC

2 tests failed.
REGRESSION:  org.apache.solr.cloud.ShardSplitTest.testDistribSearch

Error Message:
Server at http://127.0.0.1:58757 returned non ok status:500, message:Server Error

Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:58757 returned non ok status:500, message:Server Error
        at __randomizedtesting.SeedInfo.seed([2EE751C992E37A1D:AF01DFD1E5BC1A21]:0)
        at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
        at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
        at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
        at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
        at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
        at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
        at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
        at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
        at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
        at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
        at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
        at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
        at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
        at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
        at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
        at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
        at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
        at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
        at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
        at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
        at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
        at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
        at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
        at java.lang.Thread.run(Thread.java:724)


REGRESSION:  org.apache.solr.cloud.SyncSliceTest.testDistribSearch

Error Message:
shard1 is not consistent.  Got 305 from http://127.0.0.1:60378/collection1lastClient and got 256 from http://127.0.0.1:60397/collection1

Stack Trace:
java.lang.AssertionError: shard1 is not consistent.  Got 305 from http://127.0.0.1:60378/collection1lastClient and got 256 from http://127.0.0.1:60397/collection1
        at __randomizedtesting.SeedInfo.seed([2EE751C992E37A1D:AF01DFD1E5BC1A21]:0)
        at org.junit.Assert.fail(Assert.java:93)
        at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1045)
        at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:237)
        at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
        at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
        at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
        at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
        at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
        at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
        at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
        at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
        at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
        at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
        at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
        at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
        at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
        at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
        at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
        at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
        at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
        at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
        at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
        at java.lang.Thread.run(Thread.java:724)




Build Log:
[...truncated 9460 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4]   2> 686392 T2009 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 686399 T2009 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\solrtest-ShardSplitTest-1372395294173
[junit4:junit4]   2> 686402 T2009 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 686403 T2010 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 686502 T2009 oasc.ZkTestServer.run start zk server on port:58738
[junit4:junit4]   2> 686505 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 686518 T2016 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b604c90 name:ZooKeeperConnection Watcher:127.0.0.1:58738 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 686518 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 686518 T2009 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 686526 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 686528 T2018 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6ce3657b name:ZooKeeperConnection Watcher:127.0.0.1:58738/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 686528 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 686528 T2009 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 686534 T2009 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 686539 T2009 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 686543 T2009 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 686548 T2009 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 686549 T2009 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 686561 T2009 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema15.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 686563 T2009 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 686567 T2009 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 686568 T2009 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 686572 T2009 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 686572 T2009 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 686578 T2009 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 686578 T2009 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 686583 T2009 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 686584 T2009 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 686590 T2009 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 686590 T2009 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 686596 T2009 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 686596 T2009 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 686603 T2009 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 686603 T2009 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 686612 T2011 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f89224de60001, likely client has closed socket
[junit4:junit4]   2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2>
[junit4:junit4]   2> 687062 T2009 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 687067 T2009 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58745
[junit4:junit4]   2> 687067 T2009 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 687067 T2009 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 687068 T2009 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372395294384
[junit4:junit4]   2> 687068 T2009 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372395294384\solr.xml
[junit4:junit4]   2> 687068 T2009 oasc.CoreContainer.<init> New CoreContainer 333624319
[junit4:junit4]   2> 687069 T2009 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372395294384\'
[junit4:junit4]   2> 687069 T2009 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372395294384\'
[junit4:junit4]   2> 687205 T2009 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 687205 T2009 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 687206 T2009 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 687206 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 687207 T2009 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 687208 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 687209 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 687209 T2009 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 687210 T2009 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 687210 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 687220 T2009 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 687221 T2009 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58738/solr
[junit4:junit4]   2> 687221 T2009 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 687222 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 687241 T2029 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4ab64d29 name:ZooKeeperConnection Watcher:127.0.0.1:58738 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 687242 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 687244 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 687252 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 687255 T2031 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@313b2248 name:ZooKeeperConnection Watcher:127.0.0.1:58738/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 687255 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 687258 T2009 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 687264 T2009 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 687269 T2009 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 687272 T2009 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58745_
[junit4:junit4]   2> 687274 T2009 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58745_
[junit4:junit4]   2> 687279 T2009 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 687287 T2009 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 687291 T2009 oasc.Overseer.start Overseer (id=89941297999511555-127.0.0.1:58745_-n_0000000000) starting
[junit4:junit4]   2> 687298 T2009 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 687304 T2033 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 687305 T2009 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 687310 T2009 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 687314 T2009 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4]   2> 687319 T2032 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 687323 T2034 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 687323 T2034 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 687326 T2034 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4]   2> 688828 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 688829 T2032 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:58745_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58745"}
[junit4:junit4]   2> 688829 T2032 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 688829 T2032 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 688855 T2031 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> 689326 T2034 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4]   2> 689326 T2034 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372395294384\collection1
[junit4:junit4]   2> 689326 T2034 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 689328 T2034 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 689328 T2034 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 689332 T2034 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372395294384\collection1\'
[junit4:junit4]   2> 689338 T2034 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1372395294384/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 689341 T2034 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1372395294384/collection1/lib/README' to classloader
[junit4:junit4]   2> 689400 T2034 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 689480 T2034 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 689483 T2034 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 689487 T2034 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 690105 T2034 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 690109 T2034 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 690111 T2034 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 690117 T2034 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 690152 T2034 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 690153 T2034 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372395294384\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1372395294172/control/data\
[junit4:junit4]   2> 690153 T2034 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52b4e7ec
[junit4:junit4]   2> 690153 T2034 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372395294172/control/data\
[junit4:junit4]   2> 690153 T2034 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1372395294172/control/data\index/
[junit4:junit4]   2> 690153 T2034 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1372395294172\control\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 690154 T2034 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372395294172/control/data\index
[junit4:junit4]   2> 690159 T2034 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@50615756 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7467291c),segFN=segments_1,generation=1}
[junit4:junit4]   2> 690159 T2034 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 690162 T2034 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 690162 T2034 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 690162 T2034 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 690163 T2034 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 690164 T2034 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 690164 T2034 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 690164 T2034 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 690164 T2034 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 690165 T2034 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 690174 T2034 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 690180 T2034 oass.SolrIndexSearcher.<init> Opening Searcher@48eb9db6 main
[junit4:junit4]   2> 690181 T2034 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 690182 T2034 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 690187 T2034 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 690188 T2034 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58745 collection:control_collection shard:shard1
[junit4:junit4]   2> 690188 T2035 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@48eb9db6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 690190 T2034 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 690206 T2034 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4]   2> 690212 T2034 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 690212 T2034 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 690212 T2034 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58745/collection1/
[junit4:junit4]   2> 690212 T2034 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 690212 T2034 oasc.SyncStrategy.syncToMe http://127.0.0.1:58745/collection1/ has no replicas
[junit4:junit4]   2> 690212 T2034 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58745/collection1/ shard1
[junit4:junit4]   2> 690212 T2034 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 690369 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 690399 T2031 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> 690428 T2034 oasc.ZkController.register We are http://127.0.0.1:58745/collection1/ and leader is http://127.0.0.1:58745/collection1/
[junit4:junit4]   2> 690428 T2034 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58745
[junit4:junit4]   2> 690428 T2034 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 690429 T2034 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 690429 T2034 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 690445 T2034 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 690448 T2009 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 690450 T2009 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 690451 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 690466 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 690469 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 690472 T2038 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@53394daa name:ZooKeeperConnection Watcher:127.0.0.1:58738/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 690473 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 690474 T2009 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4]   2> 690477 T2009 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 690913 T2009 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 690917 T2009 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58757
[junit4:junit4]   2> 690917 T2009 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 690917 T2009 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 690918 T2009 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372395298249
[junit4:junit4]   2> 690918 T2009 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372395298249\solr.xml
[junit4:junit4]   2> 690918 T2009 oasc.CoreContainer.<init> New CoreContainer 1119862289
[junit4:junit4]   2> 690918 T2009 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372395298249\'
[junit4:junit4]   2> 690918 T2009 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372395298249\'
[junit4:junit4]   2> 691036 T2009 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 691036 T2009 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 691036 T2009 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 691037 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 691037 T2009 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 691038 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 691038 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 691039 T2009 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 691039 T2009 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 691040 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 691047 T2009 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 691047 T2009 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58738/solr
[junit4:junit4]   2> 691047 T2009 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 691050 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 691069 T2049 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f9b238 name:ZooKeeperConnection Watcher:127.0.0.1:58738 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 691070 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 691075 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 691076 T2011 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f89224de60005, likely client has closed socket
[junit4:junit4]   2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2>
[junit4:junit4]   2> 691085 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 691089 T2051 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@63ce3c6 name:ZooKeeperConnection Watcher:127.0.0.1:58738/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 691089 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 691096 T2009 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4]   2> 691917 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 691919 T2032 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:58745_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58745"}
[junit4:junit4]   2> 691939 T2031 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> 691940 T2051 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> 691940 T2038 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> 692101 T2009 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58757_
[junit4:junit4]   2> 692106 T2009 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58757_
[junit4:junit4]   2> 692117 T2031 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 692117 T2031 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> 692119 T2051 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 692119 T2051 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> 692119 T2038 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 692121 T2038 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> 692143 T2052 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 692143 T2052 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 692148 T2052 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4]   2> 693458 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 693460 T2032 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:58757_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58757"}
[junit4:junit4]   2> 693460 T2032 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 693460 T2032 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 693481 T2038 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> 693482 T2031 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> 693483 T2051 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> 694148 T2052 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4]   2> 694148 T2052 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372395298249\collection1
[junit4:junit4]   2> 694148 T2052 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 694149 T2052 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 694149 T2052 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 694152 T2052 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372395298249\collection1\'
[junit4:junit4]   2> 694153 T2052 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1372395298249/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 694154 T2052 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1372395298249/collection1/lib/README' to classloader
[junit4:junit4]   2> 694233 T2052 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 694303 T2052 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 694305 T2052 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 694309 T2052 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 694964 T2052 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 694968 T2052 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 694970 T2052 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 694975 T2052 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 695010 T2052 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 695011 T2052 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372395298249\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty1\
[junit4:junit4]   2> 695011 T2052 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52b4e7ec
[junit4:junit4]   2> 695011 T2052 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty1\
[junit4:junit4]   2> 695012 T2052 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty1\index/
[junit4:junit4]   2> 695012 T2052 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1372395294172\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 695013 T2052 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty1\index
[junit4:junit4]   2> 695017 T2052 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7d944c46 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ae11c24),segFN=segments_1,generation=1}
[junit4:junit4]   2> 695017 T2052 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 695021 T2052 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 695022 T2052 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 695023 T2052 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 695023 T2052 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 695024 T2052 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 695024 T2052 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 695025 T2052 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 695025 T2052 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 695026 T2052 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 695037 T2052 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 695043 T2052 oass.SolrIndexSearcher.<init> Opening Searcher@5a1da32 main
[junit4:junit4]   2> 695045 T2052 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 695045 T2052 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 695049 T2053 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5a1da32 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 695052 T2052 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 695052 T2052 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58757 collection:collection1 shard:shard1
[junit4:junit4]   2> 695055 T2052 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 695073 T2052 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4]   2> 695078 T2052 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 695078 T2052 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 695078 T2052 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58757/collection1/
[junit4:junit4]   2> 695078 T2052 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 695078 T2052 oasc.SyncStrategy.syncToMe http://127.0.0.1:58757/collection1/ has no replicas
[junit4:junit4]   2> 695078 T2052 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58757/collection1/ shard1
[junit4:junit4]   2> 695078 T2052 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 696498 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 696533 T2038 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> 696534 T2051 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> 696533 T2031 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> 696569 T2052 oasc.ZkController.register We are http://127.0.0.1:58757/collection1/ and leader is http://127.0.0.1:58757/collection1/
[junit4:junit4]   2> 696569 T2052 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58757
[junit4:junit4]   2> 696569 T2052 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 696570 T2052 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 696570 T2052 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 696577 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 696580 T2009 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 696580 T2009 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 696581 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 697064 T2009 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 697068 T2009 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58766
[junit4:junit4]   2> 697068 T2009 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 697069 T2009 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 697069 T2009 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372395304371
[junit4:junit4]   2> 697069 T2009 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372395304371\solr.xml
[junit4:junit4]   2> 697069 T2009 oasc.CoreContainer.<init> New CoreContainer 2121453925
[junit4:junit4]   2> 697069 T2009 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372395304371\'
[junit4:junit4]   2> 697071 T2009 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372395304371\'
[junit4:junit4]   2> 697207 T2009 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 697208 T2009 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 697208 T2009 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 697208 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 697209 T2009 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 697209 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 697209 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 697209 T2009 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 697209 T2009 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 697210 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 697217 T2009 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 697219 T2009 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58738/solr
[junit4:junit4]   2> 697219 T2009 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 697220 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 697237 T2065 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@33ebc13c name:ZooKeeperConnection Watcher:127.0.0.1:58738 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 697238 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 697243 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 697250 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 697254 T2067 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@79c7c603 name:ZooKeeperConnection Watcher:127.0.0.1:58738/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 697254 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 697262 T2009 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4]   2> 698056 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 698058 T2032 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:58757_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58757"}
[junit4:junit4]   2> 698074 T2031 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> 698075 T2067 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> 698075 T2038 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> 698076 T2051 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> 698267 T2009 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58766_
[junit4:junit4]   2> 698272 T2009 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58766_
[junit4:junit4]   2> 698282 T2031 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 698282 T2031 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> 698282 T2051 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 698283 T2051 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> 698282 T2067 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 698282 T2038 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 698286 T2038 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> 698285 T2067 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> 698306 T2068 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 698307 T2068 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 698309 T2068 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4]   2> 699591 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 699593 T2032 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:58766_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58766"}
[junit4:junit4]   2> 699593 T2032 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 699593 T2032 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 699612 T2038 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> 699613 T2031 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> 699615 T2051 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> 699615 T2067 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> 700309 T2068 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4]   2> 700309 T2068 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372395304371\collection1
[junit4:junit4]   2> 700310 T2068 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 700312 T2068 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 700312 T2068 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 700318 T2068 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372395304371\collection1\'
[junit4:junit4]   2> 700321 T2068 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1372395304371/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 700324 T2068 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1372395304371/collection1/lib/README' to classloader
[junit4:junit4]   2> 700402 T2068 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 700471 T2068 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 700474 T2068 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 700483 T2068 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 701101 T2068 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 701104 T2068 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 701106 T2068 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 701114 T2068 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 701152 T2068 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 701154 T2068 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372395304371\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty2\
[junit4:junit4]   2> 701154 T2068 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52b4e7ec
[junit4:junit4]   2> 701155 T2068 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty2\
[junit4:junit4]   2> 701155 T2068 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty2\index/
[junit4:junit4]   2> 701155 T2068 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1372395294172\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 701156 T2068 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty2\index
[junit4:junit4]   2> 701162 T2068 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@68535b3f lockFactory=org.apache.lucene.store.NativeFSLockFactory@18d3e4e4),segFN=segments_1,generation=1}
[junit4:junit4]   2> 701162 T2068 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 701166 T2068 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 701166 T2068 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 701167 T2068 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 701173 T2068 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 701174 T2068 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 701174 T2068 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 701174 T2068 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 701175 T2068 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 701175 T2068 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 701186 T2068 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 701192 T2068 oass.SolrIndexSearcher.<init> Opening Searcher@43d104ed main
[junit4:junit4]   2> 701194 T2068 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 701194 T2068 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 701201 T2069 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@43d104ed main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 701202 T2068 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 701203 T2068 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58766 collection:collection1 shard:shard2
[junit4:junit4]   2> 701203 T2068 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 701223 T2068 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
[junit4:junit4]   2> 701229 T2068 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 701229 T2068 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 701229 T2068 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58766/collection1/
[junit4:junit4]   2> 701229 T2068 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 701229 T2068 oasc.SyncStrategy.syncToMe http://127.0.0.1:58766/collection1/ has no replicas
[junit4:junit4]   2> 701231 T2068 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58766/collection1/ shard2
[junit4:junit4]   2> 701231 T2068 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 702631 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 702662 T2038 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> 702663 T2051 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> 702663 T2031 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> 702663 T2067 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> 702670 T2068 oasc.ZkController.register We are http://127.0.0.1:58766/collection1/ and leader is http://127.0.0.1:58766/collection1/
[junit4:junit4]   2> 702670 T2068 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58766
[junit4:junit4]   2> 702671 T2068 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 702671 T2068 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 702672 T2068 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 702678 T2068 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 702683 T2009 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 702684 T2009 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 702685 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 703102 T2009 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 703107 T2009 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58775
[junit4:junit4]   2> 703108 T2009 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 703109 T2009 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 703109 T2009 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372395310474
[junit4:junit4]   2> 703110 T2009 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372395310474\solr.xml
[junit4:junit4]   2> 703110 T2009 oasc.CoreContainer.<init> New CoreContainer 1565871437
[junit4:junit4]   2> 703111 T2009 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372395310474\'
[junit4:junit4]   2> 703112 T2009 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372395310474\'
[junit4:junit4]   2> 703233 T2009 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 703233 T2009 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 703234 T2009 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 703234 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 703235 T2009 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 703235 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 703235 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 703236 T2009 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 703236 T2009 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 703236 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 703243 T2009 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 703244 T2009 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58738/solr
[junit4:junit4]   2> 703244 T2009 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 703245 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 703261 T2081 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6428550c name:ZooKeeperConnection Watcher:127.0.0.1:58738 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 703262 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 703266 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 703276 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 703286 T2083 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2be2be04 name:ZooKeeperConnection Watcher:127.0.0.1:58738/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 703286 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 703294 T2009 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4]   2> 704186 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 704187 T2032 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:58766_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58766"}
[junit4:junit4]   2> 704201 T2038 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> 704201 T2031 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> 704202 T2051 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> 704202 T2067 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> 704202 T2083 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> 704298 T2009 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58775_
[junit4:junit4]   2> 704301 T2009 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58775_
[junit4:junit4]   2> 704304 T2083 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> 704306 T2038 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 704306 T2038 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> 704307 T2051 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 704307 T2051 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> 704307 T2067 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 704307 T2067 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> 704307 T2031 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 704309 T2031 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> 704310 T2083 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 704319 T2084 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 704320 T2084 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 704323 T2084 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4]   2> 705710 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 705711 T2032 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:58775_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58775"}
[junit4:junit4]   2> 705711 T2032 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 705711 T2032 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 705728 T2038 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> 705728 T2067 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> 705729 T2083 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> 705728 T2051 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> 705728 T2031 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> 706323 T2084 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4]   2> 706323 T2084 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372395310474\collection1
[junit4:junit4]   2> 706323 T2084 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 706324 T2084 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 706324 T2084 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 706326 T2084 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372395310474\collection1\'
[junit4:junit4]   2> 706328 T2084 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1372395310474/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 706328 T2084 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1372395310474/collection1/lib/README' to classloader
[junit4:junit4]   2> 706385 T2084 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 706471 T2084 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 706474 T2084 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 706482 T2084 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 707190 T2084 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 707194 T2084 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 707196 T2084 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 707202 T2084 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 707245 T2084 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 707245 T2084 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372395310474\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty3\
[junit4:junit4]   2> 707245 T2084 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52b4e7ec
[junit4:junit4]   2> 707246 T2084 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty3\
[junit4:junit4]   2> 707246 T2084 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty3\index/
[junit4:junit4]   2> 707246 T2084 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1372395294172\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 707248 T2084 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty3\index
[junit4:junit4]   2> 707253 T2084 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@293d8814 lockFactory=org.apache.lucene.store.NativeFSLockFactory@320b1cac),segFN=segments_1,generation=1}
[junit4:junit4]   2> 707253 T2084 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 707257 T2084 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 707258 T2084 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 707258 T2084 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 707259 T2084 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 707260 T2084 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 707260 T2084 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 707260 T2084 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 707261 T2084 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 707262 T2084 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 707272 T2084 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 707280 T2084 oass.SolrIndexSearcher.<init> Opening Searcher@31d80af4 main
[junit4:junit4]   2> 707282 T2084 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 707282 T2084 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 707287 T2085 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@31d80af4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 707290 T2084 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 707291 T2084 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58775 collection:collection1 shard:shard1
[junit4:junit4]   2> 707297 T2084 oasc.ZkController.register We are http://127.0.0.1:58775/collection1/ and leader is http://127.0.0.1:58757/collection1/
[junit4:junit4]   2> 707298 T2084 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58775
[junit4:junit4]   2> 707298 T2084 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 707298 T2084 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C1155 name=collection1 org.apache.solr.core.SolrCore@701d0663 url=http://127.0.0.1:58775/collection1 node=127.0.0.1:58775_ C1155_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:58775_, base_url=http://127.0.0.1:58775}
[junit4:junit4]   2> 707299 T2086 C1155 P58775 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 707300 T2086 C1155 P58775 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 707300 T2086 C1155 P58775 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 707300 T2086 C1155 P58775 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 707301 T2084 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 707303 T2086 C1155 P58775 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 707305 T2009 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 707306 T2009 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 707307 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 707320 T2043 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 707799 T2009 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 707805 T2009 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58785
[junit4:junit4]   2> 707807 T2009 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 707808 T2009 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 707808 T2009 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372395315088
[junit4:junit4]   2> 707809 T2009 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372395315088\solr.xml
[junit4:junit4]   2> 707809 T2009 oasc.CoreContainer.<init> New CoreContainer 1383640809
[junit4:junit4]   2> 707810 T2009 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372395315088\'
[junit4:junit4]   2> 707811 T2009 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372395315088\'
[junit4:junit4]   2> 707954 T2009 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 707954 T2009 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 707955 T2009 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 707955 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 707956 T2009 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 707956 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 707956 T2009 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 707957 T2009 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 707957 T2009 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 707957 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 707965 T2009 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 707966 T2009 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58738/solr
[junit4:junit4]   2> 707966 T2009 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 707968 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 707986 T2098 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6c77248a name:ZooKeeperConnection Watcher:127.0.0.1:58738 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 707987 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 707991 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 707997 T2009 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 708002 T2100 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5be463b5 name:ZooKeeperConnection Watcher:127.0.0.1:58738/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 708002 T2009 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 708009 T2009 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4]   2> 708742 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 708743 T2032 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:58775_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58775"}
[junit4:junit4]   2> 708754 T2100 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> 708755 T2038 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> 708755 T2083 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> 708755 T2031 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> 708755 T2067 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> 708755 T2051 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> 709014 T2009 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58785_
[junit4:junit4]   2> 709017 T2009 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58785_
[junit4:junit4]   2> 709023 T2083 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> 709024 T2031 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 709024 T2031 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> 709025 T2038 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 709024 T2051 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 709024 T2100 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 709026 T2067 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 709026 T2067 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> 709026 T2051 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> 709025 T2038 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> 709026 T2100 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> 709032 T2083 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 709043 T2101 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 709044 T2101 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 709047 T2101 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4]   2> 709320 T2043 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4]   2> 709320 T2043 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node3&state=recovering&nodeName=127.0.0.1:58775_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2000
[junit4:junit4]   2> 710267 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 710268 T2032 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:58785_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58785"}
[junit4:junit4]   2> 710268 T2032 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 710268 T2032 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 710279 T2031 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> 710279 T2051 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> 710279 T2100 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> 710280 T2083 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> 710280 T2067 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> 710280 T2038 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> 711047 T2101 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4]   2> 711047 T2101 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372395315088\collection1
[junit4:junit4]   2> 711047 T2101 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 711049 T2101 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 711049 T2101 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 711052 T2101 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372395315088\collection1\'
[junit4:junit4]   2> 711054 T2101 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1372395315088/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 711054 T2101 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1372395315088/collection1/lib/README' to classloader
[junit4:junit4]   2> 711119 T2101 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 711189 T2101 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 711191 T2101 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 711196 T2101 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> ASYNC  NEW_CORE C1156 name=collection1 org.apache.solr.core.SolrCore@701d0663 url=http://127.0.0.1:58775/collection1 node=127.0.0.1:58775_ C1156_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:58775_, base_url=http://127.0.0.1:58775}
[junit4:junit4]   2> 711323 T2086 C1156 P58775 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58757/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 711323 T2086 C1156 P58775 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58775 START replicas=[http://127.0.0.1:58757/collection1/] nUpdates=100
[junit4:junit4]   2> 711323 T2086 C1156 P58775 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 711324 T2086 C1156 P58775 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 711324 T2086 C1156 P58775 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 711324 T2086 C1156 P58775 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 711325 T2086 C1156 P58775 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 711325 T2086 C1156 P58775 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58757/collection1/. core=collection1
[junit4:junit4]   2> 711325 T2086 C1156 P58775 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C1157 name=collection1 org.apache.solr.core.SolrCore@7b474796 url=http://127.0.0.1:58757/collection1 node=127.0.0.1:58757_ C1157_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58757_, base_url=http://127.0.0.1:58757, leader=true}
[junit4:junit4]   2> 711343 T2046 C1157 P58757 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4]   2> 711345 T2043 C1157 P58757 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 711359 T2043 C1157 P58757 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7d944c46 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ae11c24),segFN=segments_1,generation=1}
[junit4:junit4]   2> 711360 T2043 C1157 P58757 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 711360 T2043 C1157 P58757 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 711361 T2043 C1157 P58757 oass.SolrIndexSearcher.<init> Opening Searcher@7d28213d realtime
[junit4:junit4]   2> 711361 T2043 C1157 P58757 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 711361 T2043 C1157 P58757 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 16
[junit4:junit4]   2> ASYNC  NEW_CORE C1158 name=collection1 org.apache.solr.core.SolrCore@701d0663 url=http://127.0.0.1:58775/collection1 node=127.0.0.1:58775_ C1158_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:58775_, base_url=http://127.0.0.1:58775}
[junit4:junit4]   2> 711362 T2086 C1158 P58775 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 711362 T2086 C1158 P58775 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 711367 T2047 C1157 P58757 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 711368 T2047 C1157 P58757 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4]   2> 711368 T2086 C1158 P58775 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 711368 T2086 C1158 P58775 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 711369 T2086 C1158 P58775 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 711369 T2086 C1158 P58775 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 711378 T2086 C1158 P58775 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 711794 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 711795 T2032 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:58775_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58775"}
[junit4:junit4]   2> 711805 T2100 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> 711805 T2038 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> 711806 T2031 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> 711806 T2051 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> 711807 T2067 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> 711808 T2083 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> 711879 T2101 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 711884 T2101 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 711886 T2101 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 711891 T2101 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 711926 T2101 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 711927 T2101 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372395315088\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty4\
[junit4:junit4]   2> 711927 T2101 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52b4e7ec
[junit4:junit4]   2> 711928 T2101 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty4\
[junit4:junit4]   2> 711928 T2101 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty4\index/
[junit4:junit4]   2> 711928 T2101 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1372395294172\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 711929 T2101 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372395294172/jetty4\index
[junit4:junit4]   2> 711933 T2101 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76da92c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d14e65a),segFN=segments_1,generation=1}
[junit4:junit4]   2> 711933 T2101 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 711938 T2101 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 711938 T2101 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 711939 T2101 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 711940 T2101 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 711941 T2101 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 711941 T2101 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 711942 T2101 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 711943 T2101 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 711943 T2101 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 711953 T2101 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 711960 T2101 oass.SolrIndexSearcher.<init> Opening Searcher@5e6ea6b4 main
[junit4:junit4]   2> 711962 T2101 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 711963 T2101 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 711969 T2103 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5e6ea6b4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 711973 T2101 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 711973 T2101 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58785 collection:collection1 shard:shard2
[junit4:junit4]   2> 711980 T2101 oasc.ZkController.register We are http://127.0.0.1:58785/collection1/ and leader is http://127.0.0.1:58766/collection1/
[junit4:junit4]   2> 711980 T2101 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58785
[junit4:junit4]   2> 711980 T2101 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 711980 T2101 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C1159 name=collection1 org.apache.solr.core.SolrCore@25b9c55f url=http://127.0.0.1:58785/collection1 node=127.0.0.1:58785_ C1159_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:58785_, base_url=http://127.0.0.1:58785}
[junit4:junit4]   2> 711981 T2104 C1159 P58785 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 711982 T2104 C1159 P58785 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 711982 T2104 C1159 P58785 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 711982 T2104 C1159 P58785 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 711983 T2101 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 711985 T2104 C1159 P58785 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 711986 T2009 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 711987 T2009 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 711988 T2009 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 711999 T2058 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 712000 T2009 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 712002 T2009 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4]   2> 712002 T2009 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4]   2> 712003 T2009 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 713005 T2009 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 713318 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 713319 T2032 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:58785_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58785"}
[junit4:junit4]   2> 713327 T2031 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> 713327 T2051 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> 713327 T2100 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> 713328 T2083 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> 713328 T2067 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> 713328 T2038 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> 714000 T2058 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4]   2> 714000 T2058 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node4&state=recovering&nodeName=127.0.0.1:58785_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2001
[junit4:junit4]   2> 714007 T2009 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 715010 T2009 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> ASYNC  NEW_CORE C1160 name=collection1 org.apache.solr.core.SolrCore@25b9c55f url=http://127.0.0.1:58785/collection1 node=127.0.0.1:58785_ C1160_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:58785_, base_url=http://127.0.0.1:58785}
[junit4:junit4]   2> 716001 T2104 C1160 P58785 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58766/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 716001 T2104 C1160 P58785 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58785 START replicas=[http://127.0.0.1:58766/collection1/] nUpdates=100
[junit4:junit4]   2> 716002 T2104 C1160 P58785 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 716002 T2104 C1160 P58785 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 716002 T2104 C1160 P58785 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 716002 T2104 C1160 P58785 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 716002 T2104 C1160 P58785 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 716002 T2104 C1160 P58785 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58766/collection1/. core=collection1
[junit4:junit4]   2> 716003 T2104 C1160 P58785 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C1161 name=collection1 org.apache.solr.core.SolrCore@cee84fc url=http://127.0.0.1:58766/collection1 node=127.0.0.1:58766_ C1161_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58766_, base_url=http://127.0.0.1:58766, leader=true}
[junit4:junit4]   2> 716013 T2062 C1161 P58766 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2
[junit4:junit4]   2> 716014 T2009 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 716018 T2058 C1161 P58766 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 716022 T2058 C1161 P58766 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@68535b3f lockFactory=org.apache.lucene.store.NativeFSLockFactory@18d3e4e4),segFN=segments_1,generation=1}
[junit4:junit4]   2> 716023 T2058 C1161 P58766 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 716023 T2058 C1161 P58766 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 716023 T2058 C1161 P58766 oass.SolrIndexSearcher.<init> Opening Searcher@2b227cfa realtime
[junit4:junit4]   2> 716024 T2058 C1161 P58766 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 716024 T2058 C1161 P58766 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 8
[junit4:junit4]   2> 716025 T2104 C1160 P58785 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 716026 T2104 C1160 P58785 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 716028 T2060 C1161 P58766 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 716028 T2060 C1161 P58766 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4]   2> 716029 T2104 C1160 P58785 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 716029 T2104 C1160 P58785 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 716029 T2104 C1160 P58785 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 716029 T2104 C1160 P58785 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 716036 T2104 C1160 P58785 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 716344 T2032 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 716345 T2032 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:58785_",
[junit4:junit4]   2>  "base_url":"http://127.0.0.1:58785"}
[junit4:junit4]   2> 716361 T2031 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> 716361 T2051 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> 716362 T2067 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> 716362 T2038 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> 716362 T2100 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> 716362 T2083 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> 717015 T2009 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 717017 T2009 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4]   2> ASYNC  NEW_CORE C1162 name=collection1 org.apache.solr.core.SolrCore@25c10d53 url=http://127.0.0.1:58745/collection1 node=127.0.0.1:58745_ C1162_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58745_, base_url=http://127.0.0.1:58745, leader=true}
[junit4:junit4]   2> 717027 T2027 C1162 P58745 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 717032 T2027 C1162 P58745 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@50615756 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7467291c),segFN=segments_1,generation=1}
[junit4:junit4]   2> 717033 T2027 C1162 P58745 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 717033 T2027 C1162 P58745 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 717034 T2027 C1162 P58745 oass.SolrIndexSearcher.<init> Opening Searcher@12c47f50 main
[junit4:junit4]   2> 717034 T2027 C1162 P58745 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 717035 T2035 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12c47f50 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 717035 T2027 C1162 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4]   2> ASYNC  NEW_CORE C1163 name=collection1 org.apache.solr.core.SolrCore@7b474796 url=http://127.0.0.1:58757/collection1 node=127.0.0.1:58757_ C1163_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58757_, base_url=http://127.0.0.1:58757, leader=true}
[junit4:junit4]   2> 717041 T2046 C1163 P58757 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:58757/collection1/, StdNode: http://127.0.0.1:58775/collection1/, StdNode: http://127.0.0.1:58766/collection1/, StdNode: http://127.0.0.1:58785/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4]   2> 717047 T2043 C1163 P58757 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 717048 T2043 C1163 P58757 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 717048 T2063 C1161 P58766 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 717048 T2063 C1161 P58766 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 717049 T2043 C1163 P58757 oass.SolrIndexSearcher.<init> Opening Searcher@25959d81 main
[junit4:junit4]   2> 717050 T2053 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@25959d81 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 717051 T2043 C1163 P58757 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 717052 T2043 C1163 P58757 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 5
[junit4:junit4]   2> 717052 T2063 C1161 P58766 oass.SolrIndexSearcher.<init> Opening Searcher@6501b93 main
[junit4:junit4]   2> 717054 T2069 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6501b93 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 717054 T2063 C1161 P58766 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 717054 T2063 C1161 P58766 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 6
[junit4:junit4]   2>  C1160_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58785_, base_url=http://127.0.0.1:58785}
[junit4:junit4]   2> 717055 T2093 C1160 P58785 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> ASYNC  NEW_CORE C1164 name=collection1 org.apache.solr.core.SolrCore@701d0663 url=http://127.0.0.1:58775/collection1 node=127.0.0.1:58775_ C1164_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58775_, base_url=http://127.0.0.1:58775}
[junit4:junit4]   2> 717063 T2078 C1164 P58775 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 717065 T2093 C1160 P58785 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76da92c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d14e65a),segFN=segments_1,generation=1}
[junit4:junit4]   2> 717066 T2093 C1160 P58785 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 717067 T2093 C1160 P58785 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 717070 T2078 C1164 P58775 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@293d8814 lockFactory=org.apache.lucene.store.NativeFSLockFactory@320b1cac),segFN=segments_1,generation=1}
[junit4:junit4]   2> 717070 T2093 C1160 P58785 oass.SolrIndexSearcher.<init> Opening Searcher@88af812 main
[junit4:junit4]   2> 717071 T2078 C1164 P58775 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 717071 T2078 C1164 P58775 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 717071 T2093 C1160 P58785 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 717072 T2103 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@88af812 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 717072 T2078 C1164 P58775 oass.SolrIndexSearcher.<init> Opening Searcher@671298ae main
[junit4:junit4]   2> 717073 T2093 C1160 P58785 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 18
[junit4:junit4]   2> ASYNC  NEW_CORE C1165 name=collection1 org.apache.solr.core.SolrCore@701d0663 url=http://127.0.0.1:58775/collection1 node=127.0.0.1:58775_ C1165_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58775_, base_url=http://127.0.0.1:58775}
[junit4:junit4]   2> 717073 T2078 C1165 P58775 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 717080 T2085 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@671298ae main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4]   2> 717081 T2078 C1165 P58775 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 18
[junit4:junit4]   2> ASYNC  NEW_CORE C1166 name=collection1 org.apache.solr.core.SolrCore@7b474796 url=http://127.0.0.1:58757/collection1 node=127.0.0.1:58757_ C1166_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58757_, base_url=http://127.0.0.1:58757, leader=true}
[junit4:junit4]   2> 717081 T2046 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 40
[junit4:junit4]   2> 717083 T2009 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4]   2> 717086 T2047 C1166 P58757 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4]   2> 717089 T2079 C1165 P58775 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4]   2> ASYNC  NEW_CORE C1167 name=collection1 org.apache.solr.core.SolrCore@cee84fc url=http://127.0.0.1:58766/collection1 node=127.0.0.1:58766_ C1167_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58766_, base_url=http://127.0.0.1:58766, leader=true}
[junit4:junit4]   2> 717092 T2058 C1167 P58766 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4]   2> ASYNC  NEW_CORE C1168 name=collection1 org.apache.solr.core.SolrCore@25b9c55f url=http://127.0.0.1:58785/collection1 node=127.0.0.1:58785_ C1168_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58785_, base_url=http://127.0.0.1:58785}
[junit4:junit4]   2> 717094 T2095 C1168 P58785 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4]   2> ASYNC  NEW_CORE C1169 name=collection1 org.apache.solr.core.SolrCore@25c10d53 url=http://127.0.0.1:58745/collection1 node=127.0.0.1:58745_ C1169_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58745_, base_url=http://127.0.0.1:58745, leader=true}
[junit4:junit4]   2> 719139 T2020 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439060802307883008)} 0 3
[junit4:junit4]   2> 719156 T2078 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1439060802316271616&update.from=http://127.0.0.1:58757/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439060802316271616)} 0 7
[junit4:junit4]   2> 719160 T2093 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1439060802321514496&update.from=http://127.0.0.1:58766/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439060802321514496)} 0 2
[junit4:junit4]   2> 719161 T2062 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1439060802321514496)} 0 12
[junit4:junit4]   2> 719161 T2046 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439060802316271616)} 0 18
[junit4:junit4]   2> 719167 T2022 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1439060802339340288)]} 0 2
[junit4:junit4]   2> 719179 T2095 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1439060802347728896)]} 0 2
[junit4:junit4]   2> 719180 T2058 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1439060802347728896)]} 0 6
[junit4:junit4]   2> 719181 T2047 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0]} 0 10
[junit4:junit4]   2> 719185 T2027 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1439060802357166080)]} 0 2
[junit4:junit4]   2> 719196 T2079 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1439060802361360384)]} 0 1
[junit4:junit4]   2> 719197 T2042 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1439060802361360384)]} 0 10
[junit4:junit4]   2> 719201 T2024 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1439060802374991872)]} 0 0
[junit4:junit4]   2> 719215 T2074 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1439060802385477632)]} 0 0
[junit4:junit4]   2> 719216 T2044 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!2 (1439060802385477632)]} 0 6
[junit4:junit4]   2> 719217 T2096 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2]} 0 12
[junit4:junit4]   2> 719220 T2026 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1439060802394914816)]} 0 1
[junit4:junit4]   2> 719231 T2091 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1439060802401206272)]} 0 1
[junit4:junit4]   2> 719231 T2059 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1439060802401206272)]} 0 6
[junit4:junit4]   2> 719232 T2045 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3]} 0 9
[junit4:junit4]   2> 719234 T2025 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1439060802410643456)]} 0 0
[junit4:junit4]   2> 719239 T2092 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1439060802412740608)]} 0 0
[junit4:junit4]   2> 719240 T2060 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1439060802412740608)]} 0 4
[junit4:junit4]   2> 719244 T2020 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1439060802421129216)]} 0 0
[junit4:junit4]   2> 719250 T2094 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1439060802424274944)]} 0 0
[junit4:junit4]   2> 719251 T2061 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1439060802424274944)]} 0 4
[junit4:junit4]   2> 719255 T2022 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1439060802431614976)]} 0 1
[junit4:junit4]   2> 719264 T2075 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1439060802438955008)]} 0 0
[junit4:junit4]   2> 719266 T2043 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1439060802438955008)]} 0 5
[junit4:junit4]   2> 719267 T2093 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6]} 0 9
[junit4:junit4]   2> 719269 T2027 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1439060802447343616)]} 0 0
[junit4:junit4]   2> 719277 T2076 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1439060802453635072)]} 0 0
[junit4:junit4]   2> 719278 T2046 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1439060802453635072)]} 0 4
[junit4:junit4]   2> 719279 T2063 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7]} 0 6
[junit4:junit4]   2> 719281 T2024 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1439060802459926528)]} 0 0
[junit4:junit4]   2> 719291 T2078 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1439060802467266560)]} 0 0
[junit4:junit4]   2> 719292 T2047 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58775/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!8 (1439060802467266560)]} 0 4
[junit4:junit4]   2> 719293 T2077 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8]} 0 10
[junit4:junit4]   2> 719296 T2026 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1439060802474606592)]} 0 1
[junit4:junit4]   2> 719303 T2079 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1439060802477752320)]} 0 0
[junit4:junit4]   2> 719304 T2042 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1439060802477752320)]} 0 6
[junit4:junit4]   2> 719307 T2025 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1439060802486140928)]} 0 1
[junit4:junit4]   2> 719311 T2074 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1439060802489286656)]} 0 0
[junit4:junit4]   2> 719312 T2044 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1439060802489286656)]} 0 3
[junit4:junit4]   2> 719317 T2020 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1439060802496626688)]} 0 1
[junit4:junit4]   2> 719325 T2095 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1439060802502918144)]} 0 0
[junit4:junit4]   2> 719326 T2062 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1439060802502918144)]} 0 4
[junit4:junit4]   2> 719327 T2045 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11]} 0 8
[junit4:junit4]   2> 719330 T2022 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1439060802511306752)]} 0 0
[junit4:junit4]   2> 719338 T2096 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1439060802517598208)]} 0 0
[junit4:junit4]   2> 719339 T2058 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58775/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1439060802517598208)]} 0 4
[junit4:junit4]   2> 719340 T2075 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12]} 0 6
[junit4:junit4]   2> 719345 T2027 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1439060802525986816)]} 0 1
[junit4:junit4]   2> 719352 T2078 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1439060802531229696)]} 0 0
[junit4:junit4]   2> 719353 T2043 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58775/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1439060802531229696)]} 0 4
[junit4:junit4]   2> 719354 T2076 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13]} 0 7
[junit4:junit4]   2> 719359 T2024 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1439060802541715456)]} 0 0
[junit4:junit4]   2> 719367 T2091 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1439060802546958336)]} 0 0
[junit4:junit4]   2> 719368 T2059 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1439060802546958336)]} 0 4
[junit4:junit4]   2> 719369 T2046 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14]} 0 7
[junit4:junit4]   2> 719374 T2026 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1439060802557444096)]} 0 0
[junit4:junit4]   2> 719382 T2077 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1439060802562686976)]} 0 0
[junit4:junit4]   2> 719383 T2047 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!15 (1439060802562686976)]} 0 4
[junit4:junit4]   2> 719384 T2060 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15]} 0 7
[junit4:junit4]   2> 719388 T2025 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1439060802572124160)]} 0 0
[junit4:junit4]   2> 719397 T2079 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1439060802578415616)]} 0 0
[junit4:junit4]   2> 719399 T2042 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1439060802578415616)]} 0 5
[junit4:junit4]   2> 719400 T2061 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16]} 0 9
[junit4:junit4]   2> 719405 T2020 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1439060802588901376)]} 0 1
[junit4:junit4]   2> 719413 T2092 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1439060802595192832)]} 0 1
[junit4:junit4]   2> 719414 T2063 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58775/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!17 (1439060802595192832)]} 0 4
[junit4:junit4]   2> 719414 T2074 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17]} 0 7
[junit4:junit4]   2> 719419 T2022 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1439060802603581440)]} 0 1
[junit4:junit4]   2> 719428 T2075 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1439060802610921472)]} 0 0
[junit4:junit4]   2> 719431 T2044 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!18 (1439060802610921472)]} 0 6
[junit4:junit4]   2> 719432 T2094 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18]} 0 10
[junit4:junit4]   2> 719435 T2027 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1439060802620358656)]} 0 1
[junit4:junit4]   2> 719440 T2078 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1439060802623504384)]} 0 0
[junit4:junit4]   2> 719441 T2045 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1439060802623504384)]} 0 4
[junit4:junit4]   2> 719444 T2024 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1439060802630844416)]} 0 0
[junit4:junit4]   2> 719456 T2093 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1439060802638184448)]} 0 1
[junit4:junit4]   2> 719457 T2062 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!20 (1439060802638184448)]} 0 6
[junit4:junit4]   2> 719458 T2043 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20]} 0 10
[junit4:junit4]   2> 719462 T2026 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1439060802649718784)]} 0 0
[junit4:junit4]   2> 719470 T2076 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1439060802654961664)]} 0 0
[junit4:junit4]   2> 719472 T2046 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!21 (1439060802654961664)]} 0 5
[junit4:junit4]   2> 719473 T2058 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21]} 0 8
[junit4:junit4]   2> 719477 T2025 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1439060802664398848)]} 0 1
[junit4:junit4]   2> 719483 T2077 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1439060802668593152)]} 0 0
[junit4:junit4]   2> 719485 T2047 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1439060802668593152)]} 0 5
[junit4:junit4]   2> 719489 T2022 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1439060802675933184)]} 0 2
[junit4:junit4]   2> 719496 T2095 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1439060802682224640)]} 0 1
[junit4:junit4]   2> 719497 T2059 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1439060802682224640)]} 0 5
[junit4:junit4]   2> 719500 T2027 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1439060802688516096)]} 0 1
[junit4:junit4]   2> 719512 T2091 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1439060802697953280)]} 0 1
[junit4:junit4]   2> 719514 T2060 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!24 (1439060802697953280)]} 0 7
[junit4:junit4]   2> 719515 T2096 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24]} 0 11
[junit4:junit4]   2> 719520 T2024 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1439060802709487616)]} 0 1
[junit4:junit4]   2> 719530 T2079 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1439060802714730496)]} 0 2
[junit4:junit4]   2> 719531 T2042 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1439060802714730496)]} 0 7
[junit4:junit4]   2> 719533 T2061 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25]} 0 11
[junit4:junit4]   2> 719537 T2026 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1439060802728361984)]} 0 1
[junit4:junit4]   2> 719549 T2092 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1439060802735702016)]} 0 0
[junit4:junit4]   2> 719550 T2062 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58775/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1439060802735702016)]} 0 6
[junit4:junit4]   2> 719551 T2075 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26]} 0 11
[junit4:junit4]   2> 719555 T2020 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1439060802747236352)]} 0 1
[junit4:junit4]   2> 719562 T2078 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1439060802750382080)]} 0 0
[junit4:junit4]   2> 719563 T2045 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1439060802750382080)]} 0 5
[junit4:junit4]   2> 719567 T2025 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1439060802758770688)]} 0 1
[junit4:junit4]   2> 719578 T2077 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1439060802766110720)]} 0 0
[junit4:junit4]   2> 719579 T2043 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58775/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1439060802766110720)]} 0 6
[junit4:junit4]   2> 719580 T2076 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28]} 0 10
[junit4:junit4]   2> 719584 T2022 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1439060802777645056)]} 0 1
[junit4:junit4]   2> 719595 T2093 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1439060802784985088)]} 0 1
[junit4:junit4]   2> 719596 T2058 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1439060802784985088)]} 0 5
[junit4:junit4]   2> 719597 T2046 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29]} 0 10
[junit4:junit4]   2> 719601 T2027 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1439060802794422272)]} 0 1
[junit4:junit4]   2> 719613 T2095 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1439060802803859456)]} 0 0
[junit4:junit4]   2> 719614 T2059 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1439060802803859456)]} 0 5
[junit4:junit4]   2> 719615 T2047 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30]} 0 9
[junit4:junit4]   2> 719620 T2024 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1439060802815393792)]} 0 0
[junit4:junit4]   2> 719629 T2096 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1439060802821685248)]} 0 0
[junit4:junit4]   2> 719630 T2060 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1439060802821685248)]} 0 4
[junit4:junit4]   2> 719631 T2091 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31]} 0 8
[junit4:junit4]   2> 719636 T2026 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1439060802831122432)]} 0 1
[junit4:junit4]   2> 719644 T2079 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1439060802837413888)]} 0 0
[junit4:junit4]   2> 719645 T2042 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!32 (1439060802837413888)]} 0 4
[junit4:junit4]   2> 719646 T2061 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32]} 0 7
[junit4:junit4]   2> 719651 T2020 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1439060802847899648)]} 0 0
[junit4:junit4]   2> 719657 T2074 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1439060802851045376)]} 0 0
[junit4:junit4]   2> 719658 T2044 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1439060802851045376)]} 0 4
[junit4:junit4]   2> 719663 T2025 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1439060802858385408)]} 0 2
[junit4:junit4]   2> 719670 T2075 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1439060802864676864)]} 0 0
[junit4:junit4]   2> 719672 T2045 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1439060802864676864)]} 0 5
[junit4:junit4]   2> 719673 T2063 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34]} 0 8
[junit4:junit4]   2> 719677 T2022 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1439060802873065472)]} 0 2
[junit4:junit4]   2> 719684 T2077 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1439060802879356928)]} 0 0
[junit4:junit4]   2> 719685 T2043 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58775/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!35 (1439060802879356928)]} 0 4
[junit4:junit4]   2> 719686 T2078 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35]} 0 7
[junit4:junit4]   2> 719689 T2027 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1439060802887745536)]} 0 1
[junit4:junit4]   2> 719696 T2076 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1439060802891939840)]} 0 0
[junit4:junit4]   2> 719698 T2046 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1439060802891939840)]} 0 5
[junit4:junit4]   2> 719702 T2024 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1439060802901377024)]} 0 0
[junit4:junit4]   2> 719713 T2094 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1439060802908717056)]} 0 1
[junit4:junit4]   2> 719714 T2062 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1439060802908717056)]} 0 5
[junit4:junit4]   2> 719714 T2047 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37]} 0 8
[junit4:junit4]   2> 719718 T2026 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1439060802917105664)]} 0 1
[junit4:junit4]   2> 719726 T2093 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1439060802923397120)]} 0 0
[junit4:junit4]   2> 719727 T2058 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1439060802923397120)]} 0 4
[junit4:junit4]   2> 719728 T2092 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38]} 0 7
[junit4:junit4]   2> 719731 T2020 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1439060802931785728)]} 0 0
[junit4:junit4]   2> 719740 T2079 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1439060802938077184)]} 0 0
[junit4:junit4]   2> 719742 T2042 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!39 (1439060802938077184)]} 0 5
[junit4:junit4]   2> 719743 T2059 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39]} 0 8
[junit4:junit4]   2> 719746 T2025 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1439060802946465792)]} 0 1
[junit4:junit4]   2> 719755 T2096 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1439060802952757248)]} 0 1
[junit4:junit4]   2> 719755 T2060 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!40 (1439060802952757248)]} 0 4
[junit4:junit4]   2> 719756 T2095 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40]} 0 8
[junit4:junit4]   2> 719760 T2022 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1439060802961145856)]} 0 1
[junit4:junit4]   2> 719767 T2075 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1439060802967437312)]} 0 0
[junit4:junit4]   2> 719768 T2044 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58775/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1439060802967437312)]} 0 3
[junit4:junit4]   2> 719769 T2074 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41]} 0 7
[junit4:junit4]   2> 719772 T2027 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1439060802973728768)]} 0 1
[junit4:junit4]   2> 719777 T2077 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1439060802976874496)]} 0 0
[junit4:junit4]   2> 719779 T2045 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1439060802976874496)]} 0 5
[junit4:junit4]   2> 719783 T2024 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1439060802985263104)]} 0 1
[junit4:junit4]   2> 719788 T2091 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1439060802988408832)]} 0 0
[junit4:junit4]   2> 719789 T2061 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1439060802988408832)]} 0 4
[junit4:junit4]   2> 719791 T2026 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1439060802994700288)]} 0 0
[junit4:junit4]   2> 719798 T2078 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1439060802998894592)]} 0 0
[junit4:junit4]   2> 719800 T2043 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1439060802998894592)]} 0 5
[junit4:junit4]   2> 719802 T2020 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1439060803006234624)]} 0 0
[junit4:junit4]   2> 719809 T2076 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1439060803009380352)]} 0 0
[junit4:junit4]   2> 719810 T2046 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1439060803009380352)]} 0 5
[junit4:junit4]   2> 719814 T2025 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1439060803017768960)]} 0 1
[junit4:junit4]   2> 719819 T2094 C1168 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1439060803020914688)]} 0 0
[junit4:junit4]   2> 719822 T2063 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1439060803020914688)]} 0 4
[junit4:junit4]   2> 719824 T2022 C1169 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1439060803029303296)]} 0 0
[junit4:junit4]   2> 719832 T2079 C1165 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1439060803034546176)]} 0 0
[junit4:junit4]   2> 719834 T2047 C1166 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1439060803034546176)]} 0 5
[junit4:junit4]   2> 719835 T2062 C1167 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47]} 0 8
[junit4:junit4]   2> ASYNC  NEW_CORE C1170 name=collection1 org.apache.solr.core.SolrCore@25c10d53 url=http://127.0.0.1:58745/collection1 node=127.0.0.1:58745_ C1170_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58745_, base_url=http://127.0.0.1:58745, leader=true}
[junit4:junit4]   2> 719847 T2027 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1439060803052371968)]} 0 0
[junit4:junit4]   2> ASYNC  NEW_CORE C1171 name=collection1 org.apache.solr.core.SolrCore@701d0663 url=http://127.0.0.1:58775/collection1 node=127.0.0.1:58775_ C1171_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58775_, base_url=http://127.0.0.1:58775}
[junit4:junit4]   2> 719856 T2075 C1171 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1439060803059712000)]} 0 0
[junit4:junit4]   2> ASYNC  NEW_CORE C1172 name=collection1 org.apache.solr.core.SolrCore@7b474796 url=http://127.0.0.1:58757/collection1 node=127.0.0.1:58757_ C1172_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58757_, base_url=http://127.0.0.1:58757, leader=true}
[junit4:junit4]   2> 719858 T2042 C1172 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!48 (1439060803059712000)]} 0 5
[junit4:junit4]   2> ASYNC  NEW_CORE C1173 name=collection1 org.apache.solr.core.SolrCore@25b9c55f url=http://127.0.0.1:58785/collection1 node=127.0.0.1:58785_ C1173_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58785_, base_url=http://127.0.0.1:58785}
[junit4:junit4]   2> 719859 T2093 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48]} 0 8
[junit4:junit4]   2> 719862 T2024 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1439060803068100608)]} 0 1
[junit4:junit4]   2> 719871 T2092 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1439060803071246336)]} 0 1
[junit4:junit4]   2> ASYNC  NEW_CORE C1174 name=collection1 org.apache.solr.core.SolrCore@cee84fc url=http://127.0.0.1:58766/collection1 node=127.0.0.1:58766_ C1174_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:58766_, base_url=http://127.0.0.1:58766, leader=true}
[junit4:junit4]   2> 719872 T2058 C1174 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1439060803071246336)]} 0 8
[junit4:junit4]   2> 719876 T2026 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1439060803083829248)]} 0 1
[junit4:junit4]   2> 719886 T2096 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1439060803091169280)]} 0 0
[junit4:junit4]   2> 719888 T2059 C1174 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!50 (1439060803091169280)]} 0 5
[junit4:junit4]   2> 719889 T2044 C1172 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50]} 0 9
[junit4:junit4]   2> 719892 T2025 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1439060803100606464)]} 0 1
[junit4:junit4]   2> 719903 T2074 C1171 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1439060803107946496)]} 0 1
[junit4:junit4]   2> 719903 T2045 C1172 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!51 (1439060803107946496)]} 0 4
[junit4:junit4]   2> 719904 T2095 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51]} 0 8
[junit4:junit4]   2> 719907 T2022 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1439060803116335104)]} 0 0
[junit4:junit4]   2> 719916 T2091 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1439060803122626560)]} 0 0
[junit4:junit4]   2> 719917 T2060 C1174 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58775/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!52 (1439060803122626560)]} 0 4
[junit4:junit4]   2> 719918 T2077 C1171 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52]} 0 7
[junit4:junit4]   2> 719923 T2027 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1439060803131015168)]} 0 2
[junit4:junit4]   2> 719930 T2078 C1171 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1439060803137306624)]} 0 0
[junit4:junit4]   2> 719931 T2043 C1172 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!53 (1439060803137306624)]} 0 4
[junit4:junit4]   2> 719932 T2061 C1174 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53]} 0 7
[junit4:junit4]   2> 719935 T2024 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1439060803144646656)]} 0 1
[junit4:junit4]   2> 719943 T2076 C1171 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1439060803150938112)]} 0 0
[junit4:junit4]   2> 719945 T2046 C1172 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1439060803150938112)]} 0 5
[junit4:junit4]   2> 719946 T2094 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54]} 0 8
[junit4:junit4]   2> 719949 T2026 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1439060803159326720)]} 0 1
[junit4:junit4]   2> 719957 T2096 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1439060803165618176)]} 0 0
[junit4:junit4]   2> 719958 T2063 C1174 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1439060803165618176)]} 0 4
[junit4:junit4]   2> 719959 T2093 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55]} 0 7
[junit4:junit4]   2> 719963 T2020 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1439060803175055360)]} 0 0
[junit4:junit4]   2> 719973 T2095 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1439060803182395392)]} 0 0
[junit4:junit4]   2> 719974 T2058 C1174 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1439060803182395392)]} 0 4
[junit4:junit4]   2> 719975 T2042 C1172 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56]} 0 8
[junit4:junit4]   2> 719977 T2025 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1439060803189735424)]} 0 0
[junit4:junit4]   2> 719984 T2091 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1439060803194978304)]} 0 0
[junit4:junit4]   2> 719985 T2059 C1174 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1439060803194978304)]} 0 3
[junit4:junit4]   2> 719989 T2022 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1439060803201269760)]} 0 1
[junit4:junit4]   2> 719998 T2075 C1171 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1439060803207561216)]} 0 0
[junit4:junit4]   2> 719999 T2044 C1172 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1439060803207561216)]} 0 5
[junit4:junit4]   2> 720000 T2060 C1174 P58766 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58]} 0 8
[junit4:junit4]   2> 720002 T2027 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1439060803215949824)]} 0 0
[junit4:junit4]   2> 720012 T2074 C1171 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1439060803222241280)]} 0 0
[junit4:junit4]   2> 720014 T2045 C1172 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!59 (1439060803222241280)]} 0 6
[junit4:junit4]   2> 720015 T2094 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59]} 0 10
[junit4:junit4]   2> 720017 T2024 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1439060803231678464)]} 0 0
[junit4:junit4]   2> 720023 T2077 C1171 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1439060803234824192)]} 0 0
[junit4:junit4]   2> 720025 T2043 C1172 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1439060803234824192)]} 0 5
[junit4:junit4]   2> 720029 T2026 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1439060803243212800)]} 0 1
[junit4:junit4]   2> 720037 T2078 C1171 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1439060803249504256)]} 0 0
[junit4:junit4]   2> 720040 T2047 C1172 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58785/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!61 (1439060803249504256)]} 0 6
[junit4:junit4]   2> 720041 T2092 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61]} 0 10
[junit4:junit4]   2> 720045 T2020 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1439060803259990016)]} 0 1
[junit4:junit4]   2> 720054 T2076 C1171 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58757/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1439060803266281472)]} 0 0
[junit4:junit4]   2> 720055 T2046 C1172 P58757 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58775/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!62 (1439060803266281472)]} 0 5
[junit4:junit4]   2> 720056 T2079 C1171 P58775 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62]} 0 8
[junit4:junit4]   2> 720059 T2025 C1170 P58745 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1439060803275718656)]} 0 1
[junit4:junit4]   2> 720069 T2093 C1173 P58785 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58766/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1439060803282010112)]} 0 0
[junit4:junit4]   2> 720070 T2061 C1174 P58766 oasup.LogUpdateProc

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

ction1/leader_elect/shard1 (1)
[junit4:junit4]   1>       /solr/collections/collection1/leader_elect/shard1/election (3)
[junit4:junit4]   1>        /solr/collections/collection1/leader_elect/shard1/election/89941368712331274-core_node3-n_0000000005 (0)
[junit4:junit4]   1>        /solr/collections/collection1/leader_elect/shard1/election/89941368712331276-core_node4-n_0000000003 (0)
[junit4:junit4]   1>        /solr/collections/collection1/leader_elect/shard1/election/89941368712331278-core_node1-n_0000000004 (0)
[junit4:junit4]   1>     /solr/collections/collection1/leaders (1)
[junit4:junit4]   1>      /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "core":"collection1",
[junit4:junit4]   1>            "node_name":"127.0.0.1:60410_",
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:60410"}
[junit4:junit4]   1>    /solr/collections/control_collection (3)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        {"configName":"conf1"}
[junit4:junit4]   1>     /solr/collections/control_collection/shards (0)
[junit4:junit4]   1>     /solr/collections/control_collection/leader_elect (1)
[junit4:junit4]   1>      /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4]   1>       /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4]   1>        /solr/collections/control_collection/leader_elect/shard1/election/89941368712331267-core_node1-n_0000000000 (0)
[junit4:junit4]   1>     /solr/collections/control_collection/leaders (1)
[junit4:junit4]   1>      /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "core":"collection1",
[junit4:junit4]   1>            "node_name":"127.0.0.1:60366_",
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:60366"}
[junit4:junit4]   1>   /solr/overseer_elect (2)
[junit4:junit4]   1>    /solr/overseer_elect/election (4)
[junit4:junit4]   1>     /solr/overseer_elect/election/89941368712331276-127.0.0.1:60410_-n_0000000004 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89941368712331267-127.0.0.1:60366_-n_0000000000 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89941368712331278-127.0.0.1:60378_-n_0000000005 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89941368712331274-127.0.0.1:60397_-n_0000000003 (0)
[junit4:junit4]   1>    /solr/overseer_elect/leader (0)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        {"id":"89941368712331267-127.0.0.1:60366_-n_0000000000"}
[junit4:junit4]   1>  /zookeeper (1)
[junit4:junit4]   1>  DATA:
[junit4:junit4]   1>      
[junit4:junit4]   1>
[junit4:junit4]   2> 1903160 T5052 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=2EE751C992E37A1D -Dtests.slow=true -Dtests.locale=de_CH -Dtests.timezone=Europe/Prague -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE  138s | SyncSliceTest.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: java.lang.AssertionError: shard1 is not consistent.  Got 305 from http://127.0.0.1:60378/collection1lastClient and got 256 from http://127.0.0.1:60397/collection1
[junit4:junit4]    > at __randomizedtesting.SeedInfo.seed([2EE751C992E37A1D:AF01DFD1E5BC1A21]:0)
[junit4:junit4]    > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1045)
[junit4:junit4]    > at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:237)
[junit4:junit4]    > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4]    > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2> 1903163 T4977 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> NOTE: test params are: codec=Lucene42: {range_facet_l=PostingsFormat(name=Memory doPackFST= false), text=PostingsFormat(name=Lucene41WithOrds), _version_=PostingsFormat(name=Direct), rnd_b=PostingsFormat(name=Memory doPackFST= true), intDefault=PostingsFormat(name=Direct), timestamp=PostingsFormat(name=Memory doPackFST= false), id=PostingsFormat(name=Memory doPackFST= true), a_t=PostingsFormat(name=Memory doPackFST= false), range_facet_sl=PostingsFormat(name=Memory doPackFST= true), range_facet_si=PostingsFormat(name=Memory doPackFST= false), other_tl1=PostingsFormat(name=Direct), multiDefault=PostingsFormat(name=Memory doPackFST= false), a_si=PostingsFormat(name=Direct)}, docValues:{timestamp=DocValuesFormat(name=Lucene42)}, sim=DefaultSimilarity, locale=de_CH, timezone=Europe/Prague
[junit4:junit4]   2> NOTE: Windows 7 6.1 amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=1,free=114852824,total=282955776
[junit4:junit4]   2> NOTE: All tests run in this JVM: [FastVectorHighlighterTest, TestNumberUtils, TestMaxScoreQueryParser, TestPropInject, HdfsBasicDistributedZkTest, ChaosMonkeyNothingIsSafeTest, IndexSchemaRuntimeFieldTest, PluginInfoTest, QueryParsingTest, TestSolrQueryParser, SolrRequestParserTest, TestFieldCollectionResource, HighlighterTest, OpenExchangeRatesOrgProviderTest, HdfsUnloadDistributedZkTest, TestShardHandlerFactory, TestConfig, TestHashPartitioner, TestStressRecovery, FieldAnalysisRequestHandlerTest, TestLMJelinekMercerSimilarityFactory, SynonymTokenizerTest, BadComponentTest, LeaderElectionTest, MoreLikeThisHandlerTest, SOLR749Test, TestTrie, TestWordDelimiterFilterFactory, SortByFunctionTest, CopyFieldTest, HdfsRecoveryZkTest, MinimalSchemaTest, UUIDFieldTest, TestUniqueKeyFieldResource, TestCopyFieldCollectionResource, IndexBasedSpellCheckerTest, SolrInfoMBeanTest, TestQueryTypes, HighlighterConfigTest, TestClassNameShortening, LoggingHandlerTest, TestAtomicUpdateErrorCases, TestArbitraryIndexDir, CachingDirectoryFactoryTest, TestCloudManagedSchema, TestFaceting, NumericFieldsTest, TestSolrXml, HdfsChaosMonkeySafeLeaderTest, TestFieldResource, TestCoreContainer, SystemInfoHandlerTest, FieldMutatingUpdateProcessorTest, CurrencyFieldXmlFileTest, TestJoin, PeerSyncTest, TestBinaryResponseWriter, TestCSVLoader, DistributedTermsComponentTest, RequiredFieldsTest, TestSearchPerf, TestSolrCoreProperties, StandardRequestHandlerTest, DocValuesTest, OverseerCollectionProcessorTest, TestFastLRUCache, TestDocumentBuilder, HardAutoCommitTest, TestRemoteStreaming, CoreContainerCoreInitFailuresTest, WordBreakSolrSpellCheckerTest, TestSuggestSpellingConverter, OverseerTest, HdfsDirectoryTest, SolrCoreTest, TestSolrDeletionPolicy1, TestPseudoReturnFields, TestRangeQuery, QueryEqualityTest, ParsingFieldUpdateProcessorsTest, SignatureUpdateProcessorFactoryTest, UniqFieldsUpdateProcessorFactoryTest, TestUtils, DateFieldTest, DistanceFunctionTest, MBeansHandlerTest, TestSchemaSimilarityResource, RAMDirectoryFactoryTest, TestStressLucene, DirectUpdateHandlerOptimizeTest, ChaosMonkeySafeLeaderTest, AlternateDirectoryTest, JSONWriterTest, DOMUtilTest, TestFastWriter, StatelessScriptUpdateProcessorFactoryTest, TestPhraseSuggestions, SoftAutoCommitTest, TestSolrIndexConfig, TestPerFieldSimilarity, ShardSplitTest, SolrIndexConfigTest, TestDistributedGrouping, RegexBoostProcessorTest, TestFieldTypeCollectionResource, IndexSchemaTest, LeaderElectionIntegrationTest, SpellPossibilityIteratorTest, TestQuerySenderNoQuery, SuggesterTSTTest, TestIBSimilarityFactory, PolyFieldTest, XmlUpdateRequestHandlerTest, AssignTest, ClusterStateTest, SolrCoreCheckLockOnStartupTest, FileBasedSpellCheckerTest, HdfsLockFactoryTest, TestSolrJ, TestDistributedSearch, SuggesterFSTTest, PreAnalyzedUpdateProcessorTest, TestJmxMonitoredMap, TestSchemaResource, BadCopyFieldTest, TestDFRSimilarityFactory, TestRecovery, TestFieldTypeResource, DirectSolrConnectionTest, OpenCloseCoreStressTest, SuggesterWFSTTest, TermVectorComponentDistributedTest, TestWriterPerf, TermVectorComponentTest, BadIndexSchemaTest, LukeRequestHandlerTest, OutputWriterTest, TestBM25SimilarityFactory, ResourceLoaderTest, TestFastOutputStream, TestRTGBase, XsltUpdateRequestHandlerTest, TestXIncludeConfig, DistributedSpellCheckComponentTest, BasicFunctionalityTest, TestPartialUpdateDeduplication, TestLMDirichletSimilarityFactory, RecoveryZkTest, QueryResultKeyTest, TestReplicationHandler, BasicDistributedZkTest, BasicDistributedZk2Test, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest, SyncSliceTest]
[junit4:junit4] Completed in 137.82s, 1 test, 1 failure <<< FAILURES!

[...truncated 468 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:386: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:366: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build.xml:190: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\common-build.xml:443: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:1245: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:889: There were test failures: 312 suites, 1316 tests, 1 error, 1 failure, 39 ignored (11 assumptions)

Total time: 70 minutes 48 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_25 -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure




---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]