You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/05/25 07:21:36 UTC
[JENKINS] Lucene-Solr-4.x-Windows (64bit/jdk1.7.0_21) - Build #
2824 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Windows/2824/
Java: 64bit/jdk1.7.0_21 -XX:-UseCompressedOops -XX:+UseG1GC
2 tests failed.
REGRESSION: org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testDistribSearch
Error Message:
There are still nodes recoverying - waited for 230 seconds
Stack Trace:
java.lang.AssertionError: There are still nodes recoverying - waited for 230 seconds
at __randomizedtesting.SeedInfo.seed([7113A6CE15ACE5FC:F0F528D662F385C0]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:173)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:131)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:126)
at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI(CollectionsAPIDistributedZkTest.java:512)
at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.doTest(CollectionsAPIDistributedZkTest.java:146)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
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:601)
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:722)
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:58604 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:58604 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([7113A6CE15ACE5FC:F0F528D662F385C0]: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:208)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:133)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
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:601)
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:722)
Build Log:
[...truncated 9526 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 674961 T2327 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 674966 T2327 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\solrtest-ShardSplitTest-1369457310726
[junit4:junit4] 2> 674969 T2327 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 674971 T2328 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 675081 T2327 oasc.ZkTestServer.run start zk server on port:58585
[junit4:junit4] 2> 675083 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 675096 T2334 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5b8f21fb name:ZooKeeperConnection Watcher:127.0.0.1:58585 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 675097 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 675097 T2327 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 675119 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 675126 T2336 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3c7e102d name:ZooKeeperConnection Watcher:127.0.0.1:58585/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 675126 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 675127 T2327 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 675137 T2327 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 675145 T2327 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 675151 T2327 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 675159 T2327 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 675160 T2327 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 675172 T2327 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 675199 T2327 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 675208 T2327 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 675209 T2327 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 675215 T2327 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 675217 T2327 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 675223 T2327 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 675224 T2327 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 675230 T2327 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 675232 T2327 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 675239 T2327 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 675239 T2327 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 675246 T2327 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 675248 T2327 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 675253 T2327 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 675254 T2327 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 675269 T2329 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eda043c130001, 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:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 675703 T2327 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 675707 T2327 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58592
[junit4:junit4] 2> 675709 T2327 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 675710 T2327 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 675710 T2327 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369457311027
[junit4:junit4] 2> 675710 T2327 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369457311027\solr.xml
[junit4:junit4] 2> 675711 T2327 oasc.CoreContainer.<init> New CoreContainer 1736658968
[junit4:junit4] 2> 675711 T2327 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369457311027\'
[junit4:junit4] 2> 675712 T2327 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369457311027\'
[junit4:junit4] 2> 675842 T2327 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 675843 T2327 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 675843 T2327 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 675843 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 675844 T2327 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 675844 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 675845 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 675845 T2327 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 675845 T2327 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 675846 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 675855 T2327 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 675856 T2327 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58585/solr
[junit4:junit4] 2> 675856 T2327 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 675858 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 675875 T2347 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5c9d85fa name:ZooKeeperConnection Watcher:127.0.0.1:58585 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 675877 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 675883 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 675883 T2329 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eda043c130002, 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:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 675890 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 675894 T2349 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b014293 name:ZooKeeperConnection Watcher:127.0.0.1:58585/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 675894 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 675899 T2327 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 675907 T2327 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 675915 T2327 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 675921 T2327 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58592_
[junit4:junit4] 2> 675924 T2327 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58592_
[junit4:junit4] 2> 675932 T2327 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 675946 T2327 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 675952 T2327 oasc.Overseer.start Overseer (id=89748754316591107-127.0.0.1:58592_-n_0000000000) starting
[junit4:junit4] 2> 675963 T2327 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 675975 T2351 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 675976 T2327 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 675982 T2327 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 675988 T2327 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 675993 T2350 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 676000 T2352 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369457311027\collection1
[junit4:junit4] 2> 676001 T2352 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 676002 T2352 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 676002 T2352 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 676005 T2352 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369457311027\collection1\'
[junit4:junit4] 2> 676006 T2352 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1369457311027/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 676007 T2352 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1369457311027/collection1/lib/README' to classloader
[junit4:junit4] 2> 676067 T2352 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 676141 T2352 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 676144 T2352 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 676150 T2352 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 676854 T2352 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 676859 T2352 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 676862 T2352 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 676869 T2352 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 676915 T2352 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 676916 T2352 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369457311027\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/control/data\
[junit4:junit4] 2> 676916 T2352 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3498e8f4
[junit4:junit4] 2> 676916 T2352 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 676917 T2352 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/control/data\
[junit4:junit4] 2> 676917 T2352 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/control/data\index/
[junit4:junit4] 2> 676917 T2352 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369457310725\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 676918 T2352 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/control/data\index
[junit4:junit4] 2> 676923 T2352 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c4e3b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bb91c95),segFN=segments_1,generation=1}
[junit4:junit4] 2> 676925 T2352 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 676928 T2352 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 676929 T2352 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 676929 T2352 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 676930 T2352 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 676931 T2352 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 676931 T2352 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 676931 T2352 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 676932 T2352 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 676932 T2352 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 676944 T2352 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 676951 T2352 oass.SolrIndexSearcher.<init> Opening Searcher@129613cb main
[junit4:junit4] 2> 676951 T2352 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369457310725\control\data\tlog
[junit4:junit4] 2> 676954 T2352 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 676954 T2352 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 676958 T2353 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@129613cb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 676960 T2352 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 676960 T2352 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 677650 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 677651 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:58592_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58592"}
[junit4:junit4] 2> 677651 T2350 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 677652 T2350 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 677662 T2349 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> 678070 T2352 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 678070 T2352 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58592 collection:control_collection shard:shard1
[junit4:junit4] 2> 678073 T2352 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 678094 T2352 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 678101 T2352 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 678101 T2352 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 678102 T2352 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58592/collection1/
[junit4:junit4] 2> 678102 T2352 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 678102 T2352 oasc.SyncStrategy.syncToMe http://127.0.0.1:58592/collection1/ has no replicas
[junit4:junit4] 2> 678102 T2352 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58592/collection1/
[junit4:junit4] 2> 678103 T2352 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 679321 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 679343 T2349 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> 679406 T2352 oasc.ZkController.register We are http://127.0.0.1:58592/collection1/ and leader is http://127.0.0.1:58592/collection1/
[junit4:junit4] 2> 679406 T2352 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58592
[junit4:junit4] 2> 679406 T2352 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 679406 T2352 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 679406 T2352 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 679410 T2352 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 679412 T2327 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 679413 T2327 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 679415 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 679425 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 679428 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 679433 T2356 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@29cf52d6 name:ZooKeeperConnection Watcher:127.0.0.1:58585/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 679434 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 679436 T2327 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 679441 T2327 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 679911 T2327 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 679915 T2327 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58604
[junit4:junit4] 2> 679916 T2327 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 679917 T2327 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 679917 T2327 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369457315199
[junit4:junit4] 2> 679918 T2327 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369457315199\solr.xml
[junit4:junit4] 2> 679918 T2327 oasc.CoreContainer.<init> New CoreContainer 1726728683
[junit4:junit4] 2> 679918 T2327 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369457315199\'
[junit4:junit4] 2> 679919 T2327 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369457315199\'
[junit4:junit4] 2> 680045 T2327 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 680045 T2327 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 680046 T2327 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 680046 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 680046 T2327 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 680047 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 680047 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 680048 T2327 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 680048 T2327 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 680049 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 680057 T2327 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 680058 T2327 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58585/solr
[junit4:junit4] 2> 680058 T2327 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 680061 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 680079 T2367 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14087c4e name:ZooKeeperConnection Watcher:127.0.0.1:58585 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 680081 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 680086 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 680087 T2329 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eda043c130005, 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:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 680096 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 680101 T2369 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4373afe8 name:ZooKeeperConnection Watcher:127.0.0.1:58585/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 680102 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 680113 T2327 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 681005 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 681006 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58592__collection1",
[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:58592_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58592"}
[junit4:junit4] 2> 681028 T2369 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> 681028 T2349 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> 681029 T2356 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> 681220 T2327 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58604_
[junit4:junit4] 2> 681225 T2327 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58604_
[junit4:junit4] 2> 681232 T2356 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 681233 T2349 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 681233 T2369 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 681233 T2369 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> 681240 T2356 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 681240 T2349 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 681254 T2370 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369457315199\collection1
[junit4:junit4] 2> 681254 T2370 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 681255 T2370 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 681256 T2370 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 681258 T2370 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369457315199\collection1\'
[junit4:junit4] 2> 681260 T2370 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1369457315199/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 681261 T2370 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1369457315199/collection1/lib/README' to classloader
[junit4:junit4] 2> 681329 T2370 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 681430 T2370 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 681433 T2370 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 681443 T2370 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 682158 T2370 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 682162 T2370 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 682164 T2370 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 682171 T2370 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 682214 T2370 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 682214 T2370 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369457315199\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty1\
[junit4:junit4] 2> 682215 T2370 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3498e8f4
[junit4:junit4] 2> 682215 T2370 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 682216 T2370 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty1\
[junit4:junit4] 2> 682216 T2370 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty1\index/
[junit4:junit4] 2> 682217 T2370 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369457310725\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 682217 T2370 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty1\index
[junit4:junit4] 2> 682222 T2370 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e7dfa89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18897359),segFN=segments_1,generation=1}
[junit4:junit4] 2> 682222 T2370 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 682228 T2370 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 682228 T2370 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 682229 T2370 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 682230 T2370 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 682230 T2370 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 682231 T2370 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 682231 T2370 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 682232 T2370 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 682232 T2370 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 682245 T2370 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 682253 T2370 oass.SolrIndexSearcher.<init> Opening Searcher@7527f8aa main
[junit4:junit4] 2> 682254 T2370 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369457310725\jetty1\tlog
[junit4:junit4] 2> 682255 T2370 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 682256 T2370 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 682261 T2371 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7527f8aa main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 682264 T2370 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 682264 T2370 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 682697 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 682698 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:58604_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58604"}
[junit4:junit4] 2> 682698 T2350 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 682698 T2350 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 682713 T2369 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> 682713 T2356 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> 682714 T2349 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> 683371 T2370 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 683371 T2370 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58604 collection:collection1 shard:shard1
[junit4:junit4] 2> 683372 T2370 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 683393 T2370 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 683401 T2370 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 683402 T2370 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 683402 T2370 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58604/collection1/
[junit4:junit4] 2> 683402 T2370 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 683402 T2370 oasc.SyncStrategy.syncToMe http://127.0.0.1:58604/collection1/ has no replicas
[junit4:junit4] 2> 683402 T2370 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58604/collection1/
[junit4:junit4] 2> 683403 T2370 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 684303 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 684327 T2356 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> 684328 T2349 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> 684328 T2369 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> 684346 T2370 oasc.ZkController.register We are http://127.0.0.1:58604/collection1/ and leader is http://127.0.0.1:58604/collection1/
[junit4:junit4] 2> 684346 T2370 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58604
[junit4:junit4] 2> 684346 T2370 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 684346 T2370 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 684346 T2370 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 684350 T2370 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 684352 T2327 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 684352 T2327 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 684352 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 684771 T2327 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 684775 T2327 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58613
[junit4:junit4] 2> 684776 T2327 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 684777 T2327 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 684777 T2327 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369457320118
[junit4:junit4] 2> 684777 T2327 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369457320118\solr.xml
[junit4:junit4] 2> 684778 T2327 oasc.CoreContainer.<init> New CoreContainer 1810294015
[junit4:junit4] 2> 684778 T2327 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369457320118\'
[junit4:junit4] 2> 684779 T2327 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369457320118\'
[junit4:junit4] 2> 684893 T2327 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 684893 T2327 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 684894 T2327 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 684894 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 684894 T2327 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 684895 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 684895 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 684896 T2327 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 684897 T2327 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 684897 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 684905 T2327 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 684906 T2327 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58585/solr
[junit4:junit4] 2> 684906 T2327 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 684908 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 684923 T2383 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5f26475c name:ZooKeeperConnection Watcher:127.0.0.1:58585 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 684924 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 684931 T2329 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eda043c130007, 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:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 684931 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 684939 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 684946 T2385 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@98ff079 name:ZooKeeperConnection Watcher:127.0.0.1:58585/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 684946 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 684958 T2327 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 685827 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 685830 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58604__collection1",
[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:58604_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58604"}
[junit4:junit4] 2> 685847 T2349 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> 685848 T2369 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> 685849 T2385 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> 685848 T2356 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> 685954 T2327 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58613_
[junit4:junit4] 2> 685957 T2327 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58613_
[junit4:junit4] 2> 685962 T2349 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> 685962 T2385 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> 685962 T2356 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> 685963 T2369 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 685964 T2369 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> 685968 T2349 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 685968 T2385 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 685969 T2356 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 685978 T2386 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369457320118\collection1
[junit4:junit4] 2> 685978 T2386 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 685980 T2386 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 685980 T2386 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 685982 T2386 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369457320118\collection1\'
[junit4:junit4] 2> 685984 T2386 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1369457320118/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 685984 T2386 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1369457320118/collection1/lib/README' to classloader
[junit4:junit4] 2> 686038 T2386 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 686104 T2386 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 686107 T2386 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 686112 T2386 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 686720 T2386 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 686724 T2386 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 686727 T2386 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 686733 T2386 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 686778 T2386 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 686779 T2386 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369457320118\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty2\
[junit4:junit4] 2> 686779 T2386 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3498e8f4
[junit4:junit4] 2> 686779 T2386 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 686780 T2386 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty2\
[junit4:junit4] 2> 686780 T2386 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty2\index/
[junit4:junit4] 2> 686780 T2386 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369457310725\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 686782 T2386 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty2\index
[junit4:junit4] 2> 686786 T2386 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@51874884 lockFactory=org.apache.lucene.store.NativeFSLockFactory@145b9bc9),segFN=segments_1,generation=1}
[junit4:junit4] 2> 686787 T2386 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 686791 T2386 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 686791 T2386 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 686792 T2386 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 686793 T2386 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 686793 T2386 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 686793 T2386 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 686794 T2386 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 686794 T2386 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 686795 T2386 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 686805 T2386 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 686813 T2386 oass.SolrIndexSearcher.<init> Opening Searcher@32bc84a1 main
[junit4:junit4] 2> 686813 T2386 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369457310725\jetty2\tlog
[junit4:junit4] 2> 686815 T2386 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 686816 T2386 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 686824 T2386 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 686825 T2386 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 686827 T2387 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@32bc84a1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 687351 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 687352 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:58613_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58613"}
[junit4:junit4] 2> 687352 T2350 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 687352 T2350 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 687366 T2356 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> 687367 T2349 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> 687367 T2385 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> 687367 T2369 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> 687821 T2386 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 687821 T2386 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58613 collection:collection1 shard:shard2
[junit4:junit4] 2> 687822 T2386 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 687840 T2386 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 687845 T2386 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 687845 T2386 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 687845 T2386 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58613/collection1/
[junit4:junit4] 2> 687846 T2386 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 687846 T2386 oasc.SyncStrategy.syncToMe http://127.0.0.1:58613/collection1/ has no replicas
[junit4:junit4] 2> 687846 T2386 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58613/collection1/
[junit4:junit4] 2> 687846 T2386 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 688863 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 688882 T2356 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> 688882 T2369 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> 688882 T2385 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> 688883 T2349 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> 688917 T2386 oasc.ZkController.register We are http://127.0.0.1:58613/collection1/ and leader is http://127.0.0.1:58613/collection1/
[junit4:junit4] 2> 688917 T2386 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58613
[junit4:junit4] 2> 688917 T2386 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 688917 T2386 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 688917 T2386 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 688921 T2386 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 688921 T2327 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 688922 T2327 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 688922 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 689336 T2327 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 689341 T2327 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58622
[junit4:junit4] 2> 689341 T2327 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 689342 T2327 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 689342 T2327 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369457324693
[junit4:junit4] 2> 689343 T2327 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369457324693\solr.xml
[junit4:junit4] 2> 689343 T2327 oasc.CoreContainer.<init> New CoreContainer 1196588430
[junit4:junit4] 2> 689344 T2327 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369457324693\'
[junit4:junit4] 2> 689344 T2327 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369457324693\'
[junit4:junit4] 2> 689478 T2327 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 689478 T2327 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 689478 T2327 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 689479 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 689479 T2327 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 689480 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 689480 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 689481 T2327 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 689481 T2327 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 689481 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 689490 T2327 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 689491 T2327 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58585/solr
[junit4:junit4] 2> 689491 T2327 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 689493 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 689510 T2399 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@40c9fb7 name:ZooKeeperConnection Watcher:127.0.0.1:58585 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 689511 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 689515 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 689516 T2329 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eda043c130009, 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:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 689523 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 689527 T2401 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@35ffa460 name:ZooKeeperConnection Watcher:127.0.0.1:58585/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 689528 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 689537 T2327 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 690382 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 690383 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58613__collection1",
[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:58613_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58613"}
[junit4:junit4] 2> 690399 T2401 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> 690400 T2349 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> 690401 T2356 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> 690402 T2369 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> 690403 T2385 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> 690532 T2327 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58622_
[junit4:junit4] 2> 690538 T2327 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58622_
[junit4:junit4] 2> 690543 T2356 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> 690544 T2349 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> 690548 T2401 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 690548 T2401 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> 690548 T2369 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 690549 T2369 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> 690546 T2385 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> 690554 T2356 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 690555 T2349 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 690556 T2385 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 690567 T2402 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369457324693\collection1
[junit4:junit4] 2> 690567 T2402 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 690568 T2402 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 690568 T2402 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 690570 T2402 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369457324693\collection1\'
[junit4:junit4] 2> 690571 T2402 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1369457324693/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 690572 T2402 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1369457324693/collection1/lib/README' to classloader
[junit4:junit4] 2> 690636 T2402 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 690702 T2402 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 690704 T2402 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 690710 T2402 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 691333 T2402 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 691338 T2402 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 691339 T2402 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 691345 T2402 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 691385 T2402 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 691385 T2402 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369457324693\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty3\
[junit4:junit4] 2> 691385 T2402 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3498e8f4
[junit4:junit4] 2> 691386 T2402 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 691387 T2402 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty3\
[junit4:junit4] 2> 691387 T2402 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty3\index/
[junit4:junit4] 2> 691387 T2402 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369457310725\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 691389 T2402 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty3\index
[junit4:junit4] 2> 691393 T2402 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6919e126 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bc99aff),segFN=segments_1,generation=1}
[junit4:junit4] 2> 691393 T2402 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 691397 T2402 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 691397 T2402 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 691398 T2402 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 691398 T2402 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 691399 T2402 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 691399 T2402 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 691399 T2402 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 691400 T2402 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 691401 T2402 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 691411 T2402 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 691417 T2402 oass.SolrIndexSearcher.<init> Opening Searcher@77cc2975 main
[junit4:junit4] 2> 691418 T2402 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369457310725\jetty3\tlog
[junit4:junit4] 2> 691420 T2402 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 691420 T2402 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 691427 T2402 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 691427 T2402 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 691430 T2403 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@77cc2975 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 691898 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 691899 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:58622_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58622"}
[junit4:junit4] 2> 691899 T2350 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 691900 T2350 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 691911 T2356 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> 691912 T2369 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> 691912 T2385 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> 691912 T2349 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> 691912 T2401 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> 692426 T2402 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 692426 T2402 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58622 collection:collection1 shard:shard1
[junit4:junit4] 2> 692440 T2402 oasc.ZkController.register We are http://127.0.0.1:58622/collection1/ and leader is http://127.0.0.1:58604/collection1/
[junit4:junit4] 2> 692440 T2402 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58622
[junit4:junit4] 2> 692441 T2402 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 692441 T2402 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C388 name=collection1 org.apache.solr.core.SolrCore@230c8110 url=http://127.0.0.1:58622/collection1 node=127.0.0.1:58622_ C388_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:58622_, base_url=http://127.0.0.1:58622}
[junit4:junit4] 2> 692442 T2404 C388 P58622 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 692444 T2404 C388 P58622 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 692444 T2404 C388 P58622 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 692444 T2404 C388 P58622 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 692444 T2402 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 692447 T2404 C388 P58622 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 692449 T2327 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 692449 T2327 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 692450 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 692460 T2361 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:58622__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 692928 T2327 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 692934 T2327 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58632
[junit4:junit4] 2> 692936 T2327 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 692936 T2327 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 692937 T2327 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369457328216
[junit4:junit4] 2> 692938 T2327 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369457328216\solr.xml
[junit4:junit4] 2> 692938 T2327 oasc.CoreContainer.<init> New CoreContainer 2042787670
[junit4:junit4] 2> 692939 T2327 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369457328216\'
[junit4:junit4] 2> 692940 T2327 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369457328216\'
[junit4:junit4] 2> 693081 T2327 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 693081 T2327 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 693082 T2327 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 693082 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 693082 T2327 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 693082 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 693083 T2327 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 693083 T2327 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 693084 T2327 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 693084 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 693090 T2327 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 693091 T2327 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58585/solr
[junit4:junit4] 2> 693091 T2327 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 693094 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 693108 T2416 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12f22a55 name:ZooKeeperConnection Watcher:127.0.0.1:58585 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 693110 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 693115 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 693120 T2327 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 693125 T2418 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1483c43c name:ZooKeeperConnection Watcher:127.0.0.1:58585/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 693125 T2327 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 693137 T2327 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 693409 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 693410 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58622__collection1",
[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:58622_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58622"}
[junit4:junit4] 2> 693421 T2356 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> 693422 T2418 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> 693423 T2385 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> 693423 T2349 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> 693424 T2401 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> 693423 T2369 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> 693451 T2361 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:58622__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 693451 T2361 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:58622__collection1&state=recovering&nodeName=127.0.0.1:58622_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=991
[junit4:junit4] 2> 694075 T2327 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58632_
[junit4:junit4] 2> 694078 T2327 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58632_
[junit4:junit4] 2> 694083 T2349 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> 694083 T2356 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> 694083 T2385 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> 694084 T2401 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 694084 T2401 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> 694084 T2369 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 694085 T2369 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> 694085 T2418 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 694085 T2418 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> 694090 T2356 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 694090 T2349 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 694091 T2385 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 694100 T2419 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369457328216\collection1
[junit4:junit4] 2> 694101 T2419 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 694102 T2419 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 694102 T2419 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 694103 T2419 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369457328216\collection1\'
[junit4:junit4] 2> 694105 T2419 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1369457328216/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 694106 T2419 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1369457328216/collection1/lib/README' to classloader
[junit4:junit4] 2> 694153 T2419 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 694238 T2419 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 694241 T2419 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 694245 T2419 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 694799 T2419 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 694803 T2419 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 694805 T2419 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 694820 T2419 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 694867 T2419 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 694867 T2419 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369457328216\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty4\
[junit4:junit4] 2> 694867 T2419 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3498e8f4
[junit4:junit4] 2> 694867 T2419 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 694868 T2419 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty4\
[junit4:junit4] 2> 694868 T2419 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty4\index/
[junit4:junit4] 2> 694868 T2419 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369457310725\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 694869 T2419 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty4\index
[junit4:junit4] 2> 694873 T2419 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4ef5763d lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ac69bf1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 694873 T2419 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 694876 T2419 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 694876 T2419 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 694877 T2419 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 694878 T2419 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 694879 T2419 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 694879 T2419 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 694879 T2419 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 694880 T2419 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 694880 T2419 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 694888 T2419 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 694898 T2419 oass.SolrIndexSearcher.<init> Opening Searcher@6a5f4df2 main
[junit4:junit4] 2> 694899 T2419 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369457310725\jetty4\tlog
[junit4:junit4] 2> 694901 T2419 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 694901 T2419 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 694907 T2420 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6a5f4df2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 694910 T2419 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 694911 T2419 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C389 name=collection1 org.apache.solr.core.SolrCore@230c8110 url=http://127.0.0.1:58622/collection1 node=127.0.0.1:58622_ C389_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:58622_, base_url=http://127.0.0.1:58622}
[junit4:junit4] 2> 695244 T2404 C389 P58622 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58604/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 695245 T2404 C389 P58622 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58622 START replicas=[http://127.0.0.1:58604/collection1/] nUpdates=100
[junit4:junit4] 2> 695246 T2404 C389 P58622 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 695248 T2404 C389 P58622 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 695248 T2404 C389 P58622 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 695248 T2404 C389 P58622 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 695248 T2404 C389 P58622 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 695250 T2404 C389 P58622 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58604/collection1/. core=collection1
[junit4:junit4] 2> 695251 T2404 C389 P58622 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C390 name=collection1 org.apache.solr.core.SolrCore@5ab899d4 url=http://127.0.0.1:58604/collection1 node=127.0.0.1:58604_ C390_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58604_, base_url=http://127.0.0.1:58604, leader=true}
[junit4:junit4] 2> 695262 T2362 C390 P58604 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 695268 T2363 C390 P58604 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 695271 T2363 C390 P58604 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e7dfa89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18897359),segFN=segments_1,generation=1}
[junit4:junit4] 2> 695272 T2363 C390 P58604 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 695272 T2363 C390 P58604 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e7dfa89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18897359),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e7dfa89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18897359),segFN=segments_2,generation=2}
[junit4:junit4] 2> 695272 T2363 C390 P58604 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 695272 T2363 C390 P58604 oass.SolrIndexSearcher.<init> Opening Searcher@3a6a419e realtime
[junit4:junit4] 2> 695273 T2363 C390 P58604 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 695273 T2363 C390 P58604 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 6
[junit4:junit4] 2> 695276 T2404 C389 P58622 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 695277 T2404 C389 P58622 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 695280 T2364 C390 P58604 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 695280 T2364 C390 P58604 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 695281 T2404 C389 P58622 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 695281 T2404 C389 P58622 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 695281 T2404 C389 P58622 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 695283 T2365 C390 P58604 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 695284 T2404 C389 P58622 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 695285 T2404 C389 P58622 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty3\index.20130525074851042
[junit4:junit4] 2> 695285 T2404 C389 P58622 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@6ccdd7a1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5da97669) fullCopy=false
[junit4:junit4] 2> 695287 T2360 C390 P58604 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 695288 T2404 C389 P58622 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 695289 T2404 C389 P58622 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 695289 T2404 C389 P58622 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 695292 T2404 C389 P58622 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6919e126 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bc99aff),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6919e126 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bc99aff),segFN=segments_2,generation=2}
[junit4:junit4] 2> 695293 T2404 C389 P58622 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 695293 T2404 C389 P58622 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 695294 T2404 C389 P58622 oass.SolrIndexSearcher.<init> Opening Searcher@40bd9f40 main
[junit4:junit4] 2> 695295 T2403 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@40bd9f40 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 695295 T2404 C389 P58622 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty3\index.20130525074851042 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty3\index.20130525074851042;done=true>>]
[junit4:junit4] 2> 695295 T2404 C389 P58622 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty3\index.20130525074851042
[junit4:junit4] 2> 695296 T2404 C389 P58622 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty3\index.20130525074851042
[junit4:junit4] 2> 695296 T2404 C389 P58622 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 695296 T2404 C389 P58622 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 695297 T2404 C389 P58622 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 695297 T2404 C389 P58622 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 695300 T2404 C389 P58622 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 696126 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 696127 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:58632_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58632"}
[junit4:junit4] 2> 696127 T2350 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 696128 T2350 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 696136 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58622__collection1",
[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:58622_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58622"}
[junit4:junit4] 2> 696144 T2401 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> 696145 T2349 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> 696145 T2369 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> 696145 T2385 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> 696146 T2356 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> 696146 T2418 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> 696698 T2419 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 696698 T2419 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58632 collection:collection1 shard:shard2
[junit4:junit4] 2> 696711 T2419 oasc.ZkController.register We are http://127.0.0.1:58632/collection1/ and leader is http://127.0.0.1:58613/collection1/
[junit4:junit4] 2> 696711 T2419 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58632
[junit4:junit4] 2> 696712 T2419 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 696712 T2419 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C391 name=collection1 org.apache.solr.core.SolrCore@6661b00d url=http://127.0.0.1:58632/collection1 node=127.0.0.1:58632_ C391_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:58632_, base_url=http://127.0.0.1:58632}
[junit4:junit4] 2> 696713 T2423 C391 P58632 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 696714 T2419 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 696714 T2423 C391 P58632 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 696715 T2423 C391 P58632 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 696715 T2423 C391 P58632 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 696717 T2327 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 696718 T2327 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 696719 T2327 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 696720 T2423 C391 P58632 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 696727 T2327 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 696728 T2379 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:58632__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 696729 T2327 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 696729 T2327 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 696729 T2327 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 697494 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 697495 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58632__collection1",
[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:58632_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58632"}
[junit4:junit4] 2> 697505 T2401 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> 697506 T2349 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> 697506 T2369 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> 697506 T2385 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> 697506 T2356 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> 697506 T2418 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> 697619 T2379 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:58632__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 697619 T2379 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:58632__collection1&state=recovering&nodeName=127.0.0.1:58632_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=891
[junit4:junit4] 2> 697623 T2327 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 698516 T2327 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C391_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:58632_, base_url=http://127.0.0.1:58632}
[junit4:junit4] 2> 699401 T2423 C391 P58632 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58613/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 699401 T2423 C391 P58632 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58632 START replicas=[http://127.0.0.1:58613/collection1/] nUpdates=100
[junit4:junit4] 2> 699402 T2423 C391 P58632 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 699402 T2423 C391 P58632 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 699402 T2423 C391 P58632 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 699402 T2423 C391 P58632 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 699402 T2423 C391 P58632 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 699403 T2423 C391 P58632 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58613/collection1/. core=collection1
[junit4:junit4] 2> 699403 T2423 C391 P58632 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C392 name=collection1 org.apache.solr.core.SolrCore@79ae2916 url=http://127.0.0.1:58613/collection1 node=127.0.0.1:58613_ C392_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58613_, base_url=http://127.0.0.1:58613, leader=true}
[junit4:junit4] 2> 699412 T2378 C392 P58613 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> 699413 T2327 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 699417 T2380 C392 P58613 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 699421 T2380 C392 P58613 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@51874884 lockFactory=org.apache.lucene.store.NativeFSLockFactory@145b9bc9),segFN=segments_1,generation=1}
[junit4:junit4] 2> 699421 T2380 C392 P58613 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 699421 T2380 C392 P58613 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@51874884 lockFactory=org.apache.lucene.store.NativeFSLockFactory@145b9bc9),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@51874884 lockFactory=org.apache.lucene.store.NativeFSLockFactory@145b9bc9),segFN=segments_2,generation=2}
[junit4:junit4] 2> 699421 T2380 C392 P58613 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 699423 T2380 C392 P58613 oass.SolrIndexSearcher.<init> Opening Searcher@33676ef realtime
[junit4:junit4] 2> 699423 T2380 C392 P58613 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 699423 T2380 C392 P58613 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 6
[junit4:junit4] 2> 699425 T2423 C391 P58632 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 699425 T2423 C391 P58632 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 699428 T2381 C392 P58613 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 699428 T2381 C392 P58613 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 699429 T2423 C391 P58632 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 699429 T2423 C391 P58632 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 699430 T2423 C391 P58632 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 699433 T2376 C392 P58613 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 699434 T2423 C391 P58632 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 699435 T2423 C391 P58632 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty4\index.20130525074855192
[junit4:junit4] 2> 699435 T2423 C391 P58632 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@822b40b lockFactory=org.apache.lucene.store.NativeFSLockFactory@1064b4f5) fullCopy=false
[junit4:junit4] 2> 699439 T2377 C392 P58613 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 699441 T2423 C391 P58632 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 699442 T2423 C391 P58632 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 699442 T2423 C391 P58632 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 699445 T2423 C391 P58632 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4ef5763d lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ac69bf1),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4ef5763d lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ac69bf1),segFN=segments_2,generation=2}
[junit4:junit4] 2> 699446 T2423 C391 P58632 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 699446 T2423 C391 P58632 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 699446 T2423 C391 P58632 oass.SolrIndexSearcher.<init> Opening Searcher@14e8c830 main
[junit4:junit4] 2> 699448 T2420 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14e8c830 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 699448 T2423 C391 P58632 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty4\index.20130525074855192 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty4\index.20130525074855192;done=true>>]
[junit4:junit4] 2> 699448 T2423 C391 P58632 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty4\index.20130525074855192
[junit4:junit4] 2> 699448 T2423 C391 P58632 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ShardSplitTest-1369457310725/jetty4\index.20130525074855192
[junit4:junit4] 2> 699449 T2423 C391 P58632 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 699449 T2423 C391 P58632 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 699449 T2423 C391 P58632 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 699449 T2423 C391 P58632 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 699456 T2423 C391 P58632 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 700194 T2350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 700196 T2350 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58632__collection1",
[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:58632_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58632"}
[junit4:junit4] 2> 700218 T2401 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> 700218 T2349 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> 700219 T2418 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> 700219 T2369 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> 700220 T2385 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> 700219 T2356 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> 700306 T2327 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 700307 T2327 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C393 name=collection1 org.apache.solr.core.SolrCore@1e52c5f1 url=http://127.0.0.1:58592/collection1 node=127.0.0.1:58592_ C393_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:58592_, base_url=http://127.0.0.1:58592, leader=true}
[junit4:junit4] 2> 700316 T2344 C393 P58592 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 700319 T2344 C393 P58592 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c4e3b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bb91c95),segFN=segments_1,generation=1}
[junit4:junit4] 2> 700320 T2344 C393 P58592 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 700321 T2344 C393 P58592 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c4e3b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bb91c95),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c4e3b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bb91c95),segFN=segments_2,generation=2}
[junit4:junit4] 2> 700322 T2344 C393 P58592 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 700322 T2344 C393 P58592 oass.SolrIndexSearcher.<init> Opening Searcher@4dbad8f5 main
[junit4:junit4] 2> 700322 T2344 C393 P58592 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 700323 T2353 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4dbad8f5 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 700324 T2344 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 700330 T2379 C392 P58613 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 700332 T2379 C392 P58613 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@51874884 lockFactory=org.apache.lucene.store.NativeFSLockFactory@145b9bc9),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@51874884 lockFactory=org.apache.lucene.store.NativeFSLockFactory@145b9bc9),segFN=segments_3,generation=3}
[junit4:junit4] 2> 700332 T2379 C392 P58613 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 700332 T2379 C392 P58613 oass.SolrIndexSearcher.<init> Opening Searcher@75326567 main
[junit4:junit4] 2> 700332 T2379 C392 P58613 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 700332 T2387 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@75326567 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 700334 T2379 C392 P58613 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:58604/collection1/, StdNode: http://127.0.0.1:58622/collection1/, StdNode: http://127.0.0.1:58632/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 700338 T2363 C390 P58604 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 700339 T2363 C390 P58604 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e7dfa89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18897359),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e7dfa89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18897359),segFN=segments_3,generation=3}
[junit4:junit4] 2> 700339 T2363 C390 P58604 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 700340 T2363 C390 P58604 oass.SolrIndexSearcher.<init> Opening Searcher@613373d2 main
[junit4:junit4] 2> 700340 T2363 C390 P58604 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 700341 T2371 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@613373d2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 700342 T2363 C390 P58604 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 4
[junit4:junit4] 2> C391_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58632_, base_url=http://127.0.0.1:58632}
[junit4:junit4] 2> 700346 T2413 C391 P58632 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 700347 T2413 C391 P58632 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4ef5763d lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ac69bf1),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4ef5763d lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ac69bf1),segFN=segments_3,generation=3}
[junit4:junit4] 2> 700349 T2413 C391 P58632 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> C389_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58622_, base_url=http://127.0.0.1:58622}
[junit4:junit4] 2> 700349 T2394 C389 P58622 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 700350 T2413 C391 P58632 oass.SolrIndexSearcher.<init> Opening Searcher@21181b59 main
[junit4:junit4] 2> 700351 T2394 C389 P58622 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6919e126 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bc99aff),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6919e126 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bc99aff),segFN=segments_3,generation=3}
[junit4:junit4] 2> 700351 T2394 C389 P58622 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 700351 T2394 C389 P58622 oass.SolrIndexSearcher.<init> Opening Searcher@49743335 main
[junit4:junit4] 2> 700351 T2413 C391 P58632 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 700352 T2394 C389 P58622 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 700351 T2420 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@21181b59 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 700352 T2403 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@49743335 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 700352 T2413 C391 P58632 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> 700352 T2394 C389 P58622 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 3
[junit4:junit4] 2> 700354 T2379 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> 700356 T2327 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 700359 T2361 C390 P58604 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> 700360 T2396 C389 P58622 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> 700363 T2381 C392 P58613 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> 700366 T2414 C391 P58632 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> 702153 T2341 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435980097554219008)} 0 3
[junit4:junit4] 2> 702162 T2393 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435980097559461888&update.from=http://127.0.0.1:58604/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435980097559461888)} 0 1
[junit4:junit4] 2> 702166 T2412 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435980097565753344&update.from=http://127.0.0.1:58613/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435980097565753344)} 0 2
[junit4:junit4] 2> 702167 T2378 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435980097565753344)} 0 6
[junit4:junit4] 2> 702168 T2362 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435980097559461888)} 0 14
[junit4:junit4] 2> 702171 T2343 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1435980097576239104)]} 0 0
[junit4:junit4] 2> 702178 T2413 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1435980097579384832)]} 0 1
[junit4:junit4] 2> 702179 T2380 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1435980097579384832)]} 0 5
[junit4:junit4] 2> 702181 T2344 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1435980097586724864)]} 0 0
[junit4:junit4] 2> 702187 T2395 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1435980097589870592)]} 0 0
[junit4:junit4] 2> 702188 T2363 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1435980097589870592)]} 0 4
[junit4:junit4] 2> 702191 T2345 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1435980097597210624)]} 0 0
[junit4:junit4] 2> 702196 T2394 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1435980097600356352)]} 0 0
[junit4:junit4] 2> 702197 T2361 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1435980097600356352)]} 0 3
[junit4:junit4] 2> 702201 T2340 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1435980097606647808)]} 0 1
[junit4:junit4] 2> 702207 T2414 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1435980097608744960)]} 0 1
[junit4:junit4] 2> 702207 T2379 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1435980097608744960)]} 0 5
[junit4:junit4] 2> 702209 T2341 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1435980097616084992)]} 0 0
[junit4:junit4] 2> 702215 T2409 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1435980097619230720)]} 0 0
[junit4:junit4] 2> 702216 T2376 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1435980097619230720)]} 0 4
[junit4:junit4] 2> 702220 T2342 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1435980097626570752)]} 0 1
[junit4:junit4] 2> 702226 T2410 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1435980097629716480)]} 0 1
[junit4:junit4] 2> 702226 T2377 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1435980097629716480)]} 0 4
[junit4:junit4] 2> 702228 T2343 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1435980097636007936)]} 0 0
[junit4:junit4] 2> 702235 T2397 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1435980097639153664)]} 0 0
[junit4:junit4] 2> 702235 T2364 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1435980097639153664)]} 0 4
[junit4:junit4] 2> 702238 T2344 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1435980097646493696)]} 0 0
[junit4:junit4] 2> 702243 T2392 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1435980097649639424)]} 0 0
[junit4:junit4] 2> 702245 T2365 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1435980097649639424)]} 0 4
[junit4:junit4] 2> 702247 T2345 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1435980097655930880)]} 0 0
[junit4:junit4] 2> 702253 T2393 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1435980097658028032)]} 0 1
[junit4:junit4] 2> 702254 T2360 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1435980097658028032)]} 0 5
[junit4:junit4] 2> 702257 T2340 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1435980097665368064)]} 0 1
[junit4:junit4] 2> 702263 T2395 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1435980097669562368)]} 0 1
[junit4:junit4] 2> 702264 T2362 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1435980097669562368)]} 0 4
[junit4:junit4] 2> 702267 T2341 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1435980097676902400)]} 0 0
[junit4:junit4] 2> 702272 T2396 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1435980097680048128)]} 0 0
[junit4:junit4] 2> 702273 T2363 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1435980097680048128)]} 0 3
[junit4:junit4] 2> 702275 T2342 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1435980097685291008)]} 0 0
[junit4:junit4] 2> 702281 T2411 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1435980097688436736)]} 0 0
[junit4:junit4] 2> 702282 T2378 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1435980097688436736)]} 0 4
[junit4:junit4] 2> 702284 T2343 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1435980097694728192)]} 0 0
[junit4:junit4] 2> 702290 T2412 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1435980097697873920)]} 0 1
[junit4:junit4] 2> 702290 T2380 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1435980097697873920)]} 0 3
[junit4:junit4] 2> 702293 T2344 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1435980097704165376)]} 0 0
[junit4:junit4] 2> 702299 T2394 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1435980097706262528)]} 0 0
[junit4:junit4] 2> 702301 T2361 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1435980097706262528)]} 0 6
[junit4:junit4] 2> 702303 T2345 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1435980097714651136)]} 0 0
[junit4:junit4] 2> 702311 T2413 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1435980097719894016)]} 0 0
[junit4:junit4] 2> 702312 T2381 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1435980097719894016)]} 0 4
[junit4:junit4] 2> 702313 T2364 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14]} 0 7
[junit4:junit4] 2> 702316 T2340 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1435980097727234048)]} 0 1
[junit4:junit4] 2> 702322 T2397 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1435980097731428352)]} 0 0
[junit4:junit4] 2> 702323 T2365 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1435980097731428352)]} 0 4
[junit4:junit4] 2> 702325 T2341 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1435980097737719808)]} 0 0
[junit4:junit4] 2> 702331 T2392 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1435980097740865536)]} 0 0
[junit4:junit4] 2> 702332 T2360 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1435980097740865536)]} 0 4
[junit4:junit4] 2> 702335 T2342 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1435980097748205568)]} 0 0
[junit4:junit4] 2> 702344 T2414 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1435980097754497024)]} 0 1
[junit4:junit4] 2> 702345 T2379 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!17 (1435980097754497024)]} 0 4
[junit4:junit4] 2> 702345 T2362 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17]} 0 7
[junit4:junit4] 2> 702349 T2343 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1435980097762885632)]} 0 0
[junit4:junit4] 2> 702356 T2393 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1435980097768128512)]} 0 0
[junit4:junit4] 2> 702357 T2363 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1435980097768128512)]} 0 3
[junit4:junit4] 2> 702363 T2344 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1435980097777565696)]} 0 0
[junit4:junit4] 2> 702371 T2395 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1435980097783857152)]} 0 1
[junit4:junit4] 2> 702372 T2361 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1435980097783857152)]} 0 4
[junit4:junit4] 2> 702374 T2345 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1435980097789100032)]} 0 0
[junit4:junit4] 2> 702379 T2409 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1435980097791197184)]} 0 0
[junit4:junit4] 2> 702382 T2376 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1435980097791197184)]} 0 6
[junit4:junit4] 2> 702384 T2340 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1435980097799585792)]} 0 0
[junit4:junit4] 2> 702391 T2396 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1435980097802731520)]} 0 1
[junit4:junit4] 2> 702392 T2364 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1435980097802731520)]} 0 5
[junit4:junit4] 2> 702395 T2341 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1435980097811120128)]} 0 0
[junit4:junit4] 2> 702402 T2394 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1435980097815314432)]} 0 0
[junit4:junit4] 2> 702402 T2365 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1435980097815314432)]} 0 3
[junit4:junit4] 2> 702405 T2342 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1435980097821605888)]} 0 0
[junit4:junit4] 2> 702411 T2410 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1435980097824751616)]} 0 0
[junit4:junit4] 2> 702412 T2377 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1435980097824751616)]} 0 4
[junit4:junit4] 2> 702415 T2343 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1435980097832091648)]} 0 0
[junit4:junit4] 2> 702422 T2411 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1435980097837334528)]} 0 0
[junit4:junit4] 2> 702423 T2378 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!24 (1435980097837334528)]} 0 3
[junit4:junit4] 2> 702424 T2360 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24]} 0 7
[junit4:junit4] 2> 702427 T2344 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1435980097844674560)]} 0 0
[junit4:junit4] 2> 702434 T2397 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1435980097848868864)]} 0 0
[junit4:junit4] 2> 702436 T2362 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1435980097848868864)]} 0 5
[junit4:junit4] 2> 702436 T2380 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25]} 0 7
[junit4:junit4] 2> 702438 T2345 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1435980097856208896)]} 0 0
[junit4:junit4] 2> 702447 T2412 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1435980097862500352)]} 0 1
[junit4:junit4] 2> 702447 T2381 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1435980097862500352)]} 0 3
[junit4:junit4] 2> 702448 T2363 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26]} 0 7
[junit4:junit4] 2> 702450 T2340 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1435980097868791808)]} 0 0
[junit4:junit4] 2> 702459 T2392 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1435980097875083264)]} 0 1
[junit4:junit4] 2> 702460 T2361 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!27 (1435980097875083264)]} 0 4
[junit4:junit4] 2> 702461 T2379 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27]} 0 7
[junit4:junit4] 2> 702462 T2341 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1435980097881374720)]} 0 0
[junit4:junit4] 2> 702473 T2393 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1435980097888714752)]} 0 1
[junit4:junit4] 2> 702474 T2364 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1435980097888714752)]} 0 5
[junit4:junit4] 2> 702475 T2376 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28]} 0 9
[junit4:junit4] 2> 702478 T2342 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1435980097898151936)]} 0 0
[junit4:junit4] 2> 702486 T2413 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1435980097903394816)]} 0 0
[junit4:junit4] 2> 702487 T2377 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1435980097903394816)]} 0 4
[junit4:junit4] 2> 702488 T2365 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29]} 0 8
[junit4:junit4] 2> 702491 T2343 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1435980097911783424)]} 0 0
[junit4:junit4] 2> 702499 T2414 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1435980097915977728)]} 0 1
[junit4:junit4] 2> 702499 T2378 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1435980097915977728)]} 0 4
[junit4:junit4] 2> 702502 T2344 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1435980097923317760)]} 0 0
[junit4:junit4] 2> 702508 T2409 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1435980097925414912)]} 0 1
[junit4:junit4] 2> 702508 T2380 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1435980097925414912)]} 0 4
[junit4:junit4] 2> 702511 T2345 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1435980097932754944)]} 0 0
[junit4:junit4] 2> 702518 T2395 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1435980097935900672)]} 0 1
[junit4:junit4] 2> 702519 T2360 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1435980097935900672)]} 0 5
[junit4:junit4] 2> 702522 T2340 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1435980097944289280)]} 0 0
[junit4:junit4] 2> 702528 T2396 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1435980097947435008)]} 0 0
[junit4:junit4] 2> 702529 T2362 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1435980097947435008)]} 0 4
[junit4:junit4] 2> 702532 T2341 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1435980097954775040)]} 0 0
[junit4:junit4] 2> 702539 T2394 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1435980097958969344)]} 0 0
[junit4:junit4] 2> 702540 T2363 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1435980097958969344)]} 0 4
[junit4:junit4] 2> 702543 T2342 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1435980097966309376)]} 0 0
[junit4:junit4] 2> 702550 T2397 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1435980097970503680)]} 0 0
[junit4:junit4] 2> 702551 T2361 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1435980097970503680)]} 0 4
[junit4:junit4] 2> 702554 T2343 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1435980097977843712)]} 0 0
[junit4:junit4] 2> 702560 T2392 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1435980097980989440)]} 0 0
[junit4:junit4] 2> 702561 T2365 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1435980097980989440)]} 0 4
[junit4:junit4] 2> 702564 T2345 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1435980097988329472)]} 0 0
[junit4:junit4] 2> 702573 T2410 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1435980097994620928)]} 0 0
[junit4:junit4] 2> 702575 T2381 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1435980097994620928)]} 0 5
[junit4:junit4] 2> 702575 T2360 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37]} 0 7
[junit4:junit4] 2> 702578 T2340 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1435980098003009536)]} 0 0
[junit4:junit4] 2> 702589 T2412 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1435980098010349568)]} 0 1
[junit4:junit4] 2> 702590 T2379 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1435980098010349568)]} 0 5
[junit4:junit4] 2> 702591 T2362 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38]} 0 9
[junit4:junit4] 2> 702592 T2341 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1435980098017689600)]} 0 0
[junit4:junit4] 2> 702598 T2393 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1435980098020835328)]} 0 0
[junit4:junit4] 2> 702599 T2363 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1435980098020835328)]} 0 4
[junit4:junit4] 2> 702602 T2342 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1435980098028175360)]} 0 0
[junit4:junit4] 2> 702613 T2413 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1435980098035515392)]} 0 1
[junit4:junit4] 2> 702614 T2376 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!40 (1435980098035515392)]} 0 4
[junit4:junit4] 2> 702614 T2364 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40]} 0 9
[junit4:junit4] 2> 702616 T2343 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1435980098042855424)]} 0 0
[junit4:junit4] 2> 702628 T2396 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1435980098050195456)]} 0 1
[junit4:junit4] 2> 702628 T2361 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1435980098050195456)]} 0 5
[junit4:junit4] 2> 702629 T2378 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41]} 0 9
[junit4:junit4] 2> 702632 T2344 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1435980098059632640)]} 0 0
[junit4:junit4] 2> 702640 T2394 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1435980098064875520)]} 0 0
[junit4:junit4] 2> 702641 T2365 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1435980098064875520)]} 0 4
[junit4:junit4] 2> 702642 T2380 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42]} 0 7
[junit4:junit4] 2> 702645 T2345 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1435980098073264128)]} 0 0
[junit4:junit4] 2> 702654 T2414 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1435980098079555584)]} 0 1
[junit4:junit4] 2> 702655 T2381 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!43 (1435980098079555584)]} 0 5
[junit4:junit4] 2> 702656 T2360 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43]} 0 8
[junit4:junit4] 2> 702659 T2340 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1435980098087944192)]} 0 0
[junit4:junit4] 2> 702667 T2397 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1435980098093187072)]} 0 0
[junit4:junit4] 2> 702668 T2362 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1435980098093187072)]} 0 4
[junit4:junit4] 2> 702669 T2379 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44]} 0 8
[junit4:junit4] 2> 702672 T2341 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1435980098101575680)]} 0 0
[junit4:junit4] 2> 702679 T2392 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1435980098105769984)]} 0 0
[junit4:junit4] 2> 702680 T2363 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1435980098105769984)]} 0 4
[junit4:junit4] 2> 702682 T2342 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1435980098112061440)]} 0 0
[junit4:junit4] 2> 702692 T2409 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1435980098120450048)]} 0 0
[junit4:junit4] 2> 702693 T2377 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!46 (1435980098120450048)]} 0 4
[junit4:junit4] 2> 702694 T2364 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46]} 0 9
[junit4:junit4] 2> 702699 T2343 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1435980098127790080)]} 0 2
[junit4:junit4] 2> 702704 T2395 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1435980098133032960)]} 0 0
[junit4:junit4] 2> 702705 T2361 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1435980098133032960)]} 0 3
[junit4:junit4] 2> 702708 T2344 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1435980098139324416)]} 0 0
[junit4:junit4] 2> 702715 T2393 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1435980098142470144)]} 0 1
[junit4:junit4] 2> 702716 T2365 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1435980098142470144)]} 0 5
[junit4:junit4] 2> 702718 T2345 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1435980098149810176)]} 0 0
[junit4:junit4] 2> 702727 T2411 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1435980098156101632)]} 0 1
[junit4:junit4] 2> 702728 T2376 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!49 (1435980098156101632)]} 0 4
[junit4:junit4] 2> 702729 T2360 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49]} 0 8
[junit4:junit4] 2> 702733 T2340 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1435980098165538816)]} 0 0
[junit4:junit4] 2> 702743 T2410 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1435980098171830272)]} 0 1
[junit4:junit4] 2> 702744 T2378 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!50 (1435980098171830272)]} 0 5
[junit4:junit4] 2> 702745 T2362 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50]} 0 9
[junit4:junit4] 2> 702748 T2341 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1435980098181267456)]} 0 0
[junit4:junit4] 2> 702754 T2396 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1435980098184413184)]} 0 0
[junit4:junit4] 2> 702757 T2363 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1435980098184413184)]} 0 6
[junit4:junit4] 2> 702760 T2342 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1435980098193850368)]} 0 1
[junit4:junit4] 2> 702770 T2412 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1435980098201190400)]} 0 0
[junit4:junit4] 2> 702771 T2380 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!52 (1435980098201190400)]} 0 5
[junit4:junit4] 2> 702772 T2364 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52]} 0 9
[junit4:junit4] 2> 702777 T2343 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1435980098211676160)]} 0 2
[junit4:junit4] 2> 702785 T2394 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1435980098215870464)]} 0 0
[junit4:junit4] 2> 702787 T2361 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1435980098215870464)]} 0 7
[junit4:junit4] 2> 702791 T2344 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1435980098226356224)]} 0 1
[junit4:junit4] 2> 702799 T2397 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1435980098230550528)]} 0 1
[junit4:junit4] 2> 702800 T2365 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1435980098230550528)]} 0 6
[junit4:junit4] 2> 702806 T2345 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1435980098241036288)]} 0 1
[junit4:junit4] 2> 702816 T2413 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1435980098250473472)]} 0 0
[junit4:junit4] 2> 702817 T2381 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1435980098250473472)]} 0 3
[junit4:junit4] 2> 702818 T2360 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55]} 0 7
[junit4:junit4] 2> 702821 T2340 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1435980098257813504)]} 0 0
[junit4:junit4] 2> 702829 T2414 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1435980098264104960)]} 0 0
[junit4:junit4] 2> 702830 T2379 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1435980098264104960)]} 0 3
[junit4:junit4] 2> 702831 T2362 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56]} 0 6
[junit4:junit4] 2> 702834 T2341 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1435980098271444992)]} 0 0
[junit4:junit4] 2> 702842 T2409 C391 P58632 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1435980098275639296)]} 0 1
[junit4:junit4] 2> 702843 T2377 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1435980098275639296)]} 0 5
[junit4:junit4] 2> 702843 T2363 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57]} 0 6
[junit4:junit4] 2> 702846 T2342 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1435980098284027904)]} 0 0
[junit4:junit4] 2> 702854 T2392 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1435980098290319360)]} 0 0
[junit4:junit4] 2> 702855 T2364 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1435980098290319360)]} 0 3
[junit4:junit4] 2> 702856 T2376 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58]} 0 7
[junit4:junit4] 2> 702858 T2343 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1435980098296610816)]} 0 0
[junit4:junit4] 2> 702863 T2395 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1435980098298707968)]} 0 0
[junit4:junit4] 2> 702864 T2361 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1435980098298707968)]} 0 4
[junit4:junit4] 2> 702867 T2344 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1435980098306048000)]} 0 0
[junit4:junit4] 2> 702876 T2393 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1435980098312339456)]} 0 0
[junit4:junit4] 2> 702877 T2365 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58613/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!60 (1435980098312339456)]} 0 4
[junit4:junit4] 2> 702878 T2378 C392 P58613 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60]} 0 8
[junit4:junit4] 2> 702881 T2345 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1435980098320728064)]} 0 0
[junit4:junit4] 2> 702887 T2396 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58604/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1435980098322825216)]} 0 1
[junit4:junit4] 2> 702888 T2360 C390 P58604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1435980098322825216)]} 0 5
[junit4:junit4] 2> 702890 T2340 C393 P58592 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1435980098330165248)]} 0 0
[junit4:junit4] 2> 702899 T2394 C389 P58622 oasup.LogUpdateProcessor.finish [collection1] webapp
[...truncated too long message...]
-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-1369457966711\zookeeper\server1\data FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-1369457966711\zookeeper\server1 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-1369457966711\zookeeper FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.CollectionsAPIDistributedZkTest-1369457966711 FAILED !!!!!
[junit4:junit4] 2> 1641395 T4321 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1641398 T4321 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:59861 59861
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_1_shard1_replica4",
[junit4:junit4] 1> "node_name":"127.0.0.1:59868_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59868"}
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leaders/shard4 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_1_shard4_replica3",
[junit4:junit4] 1> "node_name":"127.0.0.1:59880_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59880"}
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leaders/shard2 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_1_shard2_replica5",
[junit4:junit4] 1> "node_name":"127.0.0.1:59889_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59889"}
[junit4:junit4] 1> /solr/collections/awholynewcollection_1/leaders/shard3 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"awholynewcollection_1_shard3_replica2",
[junit4:junit4] 1> "node_name":"127.0.0.1:59898_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59898"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (5)
[junit4:junit4] 1> /solr/overseer_elect/election/89748797307813896-127.0.0.1:59889_-n_0000000002 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89748797307813894-127.0.0.1:59880_-n_0000000001 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89748797307813891-127.0.0.1:59868_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89748797307813900-127.0.0.1:59907_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89748797307813898-127.0.0.1:59898_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89748797307813891-127.0.0.1:59868_-n_0000000000"}
[junit4:junit4] 1> /zookeeper (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=CollectionsAPIDistributedZkTest -Dtests.method=testDistribSearch -Dtests.seed=7113A6CE15ACE5FC -Dtests.slow=true -Dtests.locale=es_MX -Dtests.timezone=Etc/GMT+7 -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 313s | CollectionsAPIDistributedZkTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: There are still nodes recoverying - waited for 230 seconds
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([7113A6CE15ACE5FC:F0F528D662F385C0]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:173)
[junit4:junit4] > at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:131)
[junit4:junit4] > at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:126)
[junit4:junit4] > at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testCollectionsAPI(CollectionsAPIDistributedZkTest.java:512)
[junit4:junit4] > at org.apache.solr.cloud.CollectionsAPIDistributedZkTest.doTest(CollectionsAPIDistributedZkTest.java:146)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 1643473 T4321 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene40, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=es_MX, timezone=Etc/GMT+7
[junit4:junit4] 2> NOTE: Windows 7 6.1 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=2,threads=2,free=324621344,total=536870912
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestHashPartitioner, RegexBoostProcessorTest, FieldMutatingUpdateProcessorTest, TestCollationField, TermsComponentTest, AnalysisAfterCoreReloadTest, TestFastOutputStream, CopyFieldTest, TestFunctionQuery, TestPostingsSolrHighlighter, RequestHandlersTest, PathHierarchyTokenizerFactoryTest, TestFoldingMultitermQuery, BasicFunctionalityTest, QueryResultKeyTest, TestPhraseSuggestions, AliasIntegrationTest, TestCollationKeyRangeQueries, TestShardHandlerFactory, ShowFileRequestHandlerTest, TermVectorComponentTest, BasicDistributedZk2Test, NumericFieldsTest, XmlUpdateRequestHandlerTest, HardAutoCommitTest, CoreContainerCoreInitFailuresTest, TestRemoteStreaming, TestPHPSerializedResponseWriter, TestSolrDeletionPolicy1, LoggingHandlerTest, CachingDirectoryFactoryTest, TestUtils, RequiredFieldsTest, TestElisionMultitermQuery, ReturnFieldsTest, TestFieldTypeCollectionResource, TestRandomFaceting, QueryEqualityTest, TestComponentsName, SpellCheckComponentTest, TestSolrDeletionPolicy2, IndexSchemaRuntimeFieldTest, DocValuesTest, ZkControllerTest, ShardRoutingTest, PrimitiveFieldTypeTest, TestSolrJ, SchemaVersionSpecificBehaviorTest, SampleTest, TestGroupingSearch, PeerSyncTest, RecoveryZkTest, TestSystemIdResolver, PreAnalyzedUpdateProcessorTest, TestDynamicFieldCollectionResource, TestStressLucene, SolrIndexSplitterTest, DateFieldTest, TestReplicationHandler, IndexSchemaTest, TestPerFieldSimilarity, QueryElevationComponentTest, DistributedQueryElevationComponentTest, SolrCoreTest, TestCSVResponseWriter, TestLazyCores, TestIBSimilarityFactory, TestCopyFieldCollectionResource, TestRealTimeGet, TestFastWriter, TestSchemaSimilarityResource, TestAtomicUpdateErrorCases, IndexBasedSpellCheckerTest, TestMergePolicyConfig, ConvertedLegacyTest, EchoParamsTest, TestMaxScoreQueryParser, PrimUtilsTest, TestJoin, TimeZoneUtilsTest, TestExtendedDismaxParser, DOMUtilTest, TestWriterPerf, ShardRoutingCustomTest, ChaosMonkeyNothingIsSafeTest, TestDistributedSearch, TestJmxIntegration, StandardRequestHandlerTest, TestClassNameShortening, TestPseudoReturnFields, ShardSplitTest, TestReload, SuggesterWFSTTest, TestReversedWildcardFilterFactory, AlternateDirectoryTest, SuggesterFSTTest, ZkNodePropsTest, DocumentAnalysisRequestHandlerTest, DefaultValueUpdateProcessorTest, CoreAdminHandlerTest, ClusterStateTest, CircularListTest, LukeRequestHandlerTest, FullSolrCloudDistribCmdsTest, TestUniqueKeyFieldResource, TestStressReorder, TestSolrXMLSerializer, SolrTestCaseJ4Test, TestSchemaVersionResource, OverseerTest, NotRequiredUniqueKeyTest, UpdateParamsTest, DirectUpdateHandlerTest, DistributedSpellCheckComponentTest, SignatureUpdateProcessorFactoryTest, TestSearchPerf, TestOmitPositions, TestRTGBase, PingRequestHandlerTest, TestSolrXml, TestBM25SimilarityFactory, TestRangeQuery, TestCodecSupport, CSVRequestHandlerTest, CacheHeaderTest, TestFieldResource, TestWordDelimiterFilterFactory, HighlighterConfigTest, SOLR749Test, FieldAnalysisRequestHandlerTest, TestManagedSchema, PluginInfoTest, TestBinaryResponseWriter, SimplePostToolTest, MultiTermTest, BinaryUpdateRequestHandlerTest, OutputWriterTest, PreAnalyzedFieldTest, StatelessScriptUpdateProcessorFactoryTest, DistanceFunctionTest, TestDocumentBuilder, SuggesterTSTTest, TestSolrQueryParser, DebugComponentTest, DirectUpdateHandlerOptimizeTest, BasicDistributedZkTest, ChaosMonkeySafeLeaderTest, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest]
[junit4:junit4] Completed in 312.55s, 1 test, 1 failure <<< FAILURES!
[...truncated 463 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:386: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:366: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build.xml:181: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\common-build.xml:437: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:1243: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:887: There were test failures: 296 suites, 1234 tests, 1 error, 1 failure, 18 ignored (12 assumptions)
Total time: 71 minutes 58 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_21 -XX:-UseCompressedOops -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure