You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/05/30 20:43:30 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 1295 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/1295/
2 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:13303/_swb/v 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:13303/_swb/v returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([351B9F9EB75386E1:B4FD1186C00CE6DD]: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.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
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:53902 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:53902 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([351B9F9EB75386E1:B4FD1186C00CE6DD]: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 9611 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 885452 T2179 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 885459 T2179 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solrtest-ShardSplitTest-1369938443876
[junit4:junit4] 2> 885460 T2179 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 885461 T2180 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 885562 T2179 oasc.ZkTestServer.run start zk server on port:53894
[junit4:junit4] 2> 885563 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 885567 T2186 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@68e7243e name:ZooKeeperConnection Watcher:127.0.0.1:53894 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 885567 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 885568 T2179 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 885580 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 885582 T2188 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@381b8ba8 name:ZooKeeperConnection Watcher:127.0.0.1:53894/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 885582 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 885583 T2179 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 885587 T2179 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 885597 T2179 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 885599 T2179 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 885602 T2179 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 885602 T2179 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 885612 T2179 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 885613 T2179 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 885718 T2179 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 885719 T2179 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 885730 T2179 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 885731 T2179 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 885734 T2179 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 885735 T2179 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 885738 T2179 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 885738 T2179 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 885741 T2179 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 885742 T2179 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 885745 T2179 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 885745 T2179 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 885748 T2179 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 885749 T2179 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 886024 T2179 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 886029 T2179 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:53897
[junit4:junit4] 2> 886030 T2179 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 886031 T2179 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 886031 T2179 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369938444173
[junit4:junit4] 2> 886032 T2179 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369938444173/solr.xml
[junit4:junit4] 2> 886032 T2179 oasc.CoreContainer.<init> New CoreContainer 1288292085
[junit4:junit4] 2> 886033 T2179 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369938444173/'
[junit4:junit4] 2> 886033 T2179 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369938444173/'
[junit4:junit4] 2> 886162 T2179 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 886163 T2179 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 886163 T2179 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 886164 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 886165 T2179 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 886165 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 886166 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 886166 T2179 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 886167 T2179 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 886167 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 886185 T2179 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 886186 T2179 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53894/solr
[junit4:junit4] 2> 886186 T2179 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 886187 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 886190 T2199 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@606239fc name:ZooKeeperConnection Watcher:127.0.0.1:53894 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 886191 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 886193 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 886206 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 886208 T2201 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@695eab9b name:ZooKeeperConnection Watcher:127.0.0.1:53894/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 886208 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 886210 T2179 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 886220 T2179 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 886227 T2179 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 886229 T2179 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53897_
[junit4:junit4] 2> 886231 T2179 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53897_
[junit4:junit4] 2> 886235 T2179 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 886252 T2179 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 886262 T2179 oasc.Overseer.start Overseer (id=89780285858316291-127.0.0.1:53897_-n_0000000000) starting
[junit4:junit4] 2> 886322 T2179 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 886405 T2203 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 886405 T2179 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 886474 T2179 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 886476 T2179 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 886478 T2202 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 886483 T2204 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369938444173/collection1
[junit4:junit4] 2> 886483 T2204 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 886484 T2204 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 886484 T2204 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 886486 T2204 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369938444173/collection1/'
[junit4:junit4] 2> 886487 T2204 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1369938444173/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 886488 T2204 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1369938444173/collection1/lib/README' to classloader
[junit4:junit4] 2> 886541 T2204 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 886603 T2204 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 886705 T2204 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 886711 T2204 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 887289 T2204 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 887293 T2204 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 887296 T2204 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 887301 T2204 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 887325 T2204 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 887326 T2204 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369938444173/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369938443875/control/data/
[junit4:junit4] 2> 887326 T2204 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1936982
[junit4:junit4] 2> 887327 T2204 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 887327 T2204 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/control/data
[junit4:junit4] 2> 887328 T2204 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369938443875/control/data/index/
[junit4:junit4] 2> 887328 T2204 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369938443875/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 887329 T2204 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/control/data/index
[junit4:junit4] 2> 887333 T2204 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7656840 lockFactory=org.apache.lucene.store.NativeFSLockFactory@72570967),segFN=segments_1,generation=1}
[junit4:junit4] 2> 887334 T2204 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 887337 T2204 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 887337 T2204 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 887338 T2204 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 887338 T2204 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 887339 T2204 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 887339 T2204 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 887340 T2204 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 887340 T2204 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 887341 T2204 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 887357 T2204 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 887364 T2204 oass.SolrIndexSearcher.<init> Opening Searcher@2bff0440 main
[junit4:junit4] 2> 887365 T2204 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369938443875/control/data/tlog
[junit4:junit4] 2> 887366 T2204 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 887366 T2204 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 887370 T2205 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2bff0440 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 887372 T2204 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 887372 T2204 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 887983 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 887984 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[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:53897_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53897"}
[junit4:junit4] 2> 887984 T2202 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 887984 T2202 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 888023 T2201 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> 888379 T2204 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 888379 T2204 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53897 collection:control_collection shard:shard1
[junit4:junit4] 2> 888380 T2204 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 888406 T2204 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 888409 T2204 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 888409 T2204 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 888410 T2204 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53897/collection1/
[junit4:junit4] 2> 888410 T2204 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 888410 T2204 oasc.SyncStrategy.syncToMe http://127.0.0.1:53897/collection1/ has no replicas
[junit4:junit4] 2> 888411 T2204 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53897/collection1/
[junit4:junit4] 2> 888411 T2204 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 889527 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 889547 T2201 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> 889607 T2204 oasc.ZkController.register We are http://127.0.0.1:53897/collection1/ and leader is http://127.0.0.1:53897/collection1/
[junit4:junit4] 2> 889607 T2204 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53897
[junit4:junit4] 2> 889607 T2204 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 889607 T2204 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 889608 T2204 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 889609 T2204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 889610 T2179 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 889611 T2179 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 889612 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 889628 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 889629 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 889632 T2208 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4c49e361 name:ZooKeeperConnection Watcher:127.0.0.1:53894/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 889632 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 889633 T2179 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 889635 T2179 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 889903 T2179 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 889907 T2179 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:53902
[junit4:junit4] 2> 889908 T2179 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 889908 T2179 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 889909 T2179 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369938448051
[junit4:junit4] 2> 889909 T2179 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369938448051/solr.xml
[junit4:junit4] 2> 889910 T2179 oasc.CoreContainer.<init> New CoreContainer 160321098
[junit4:junit4] 2> 889911 T2179 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369938448051/'
[junit4:junit4] 2> 889911 T2179 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369938448051/'
[junit4:junit4] 2> 890040 T2179 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 890041 T2179 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 890041 T2179 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 890042 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 890042 T2179 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 890043 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 890043 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 890044 T2179 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 890044 T2179 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 890045 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 890061 T2179 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 890061 T2179 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53894/solr
[junit4:junit4] 2> 890062 T2179 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 890063 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 890066 T2219 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3a1dd74a name:ZooKeeperConnection Watcher:127.0.0.1:53894 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 890067 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 890081 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 890092 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 890094 T2221 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7a3172c3 name:ZooKeeperConnection Watcher:127.0.0.1:53894/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 890094 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 890103 T2179 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 891058 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 891059 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[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:53897_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53897"}
[junit4:junit4] 2> 891074 T2201 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> 891074 T2221 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> 891074 T2208 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> 891107 T2179 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53902_
[junit4:junit4] 2> 891109 T2179 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53902_
[junit4:junit4] 2> 891111 T2221 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> 891111 T2208 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> 891111 T2201 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 891112 T2201 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> 891113 T2221 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 891113 T2208 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 891124 T2222 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369938448051/collection1
[junit4:junit4] 2> 891125 T2222 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 891125 T2222 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 891125 T2222 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 891127 T2222 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369938448051/collection1/'
[junit4:junit4] 2> 891128 T2222 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1369938448051/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 891129 T2222 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1369938448051/collection1/lib/README' to classloader
[junit4:junit4] 2> 891181 T2222 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 891242 T2222 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 891344 T2222 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 891350 T2222 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 891927 T2222 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 891931 T2222 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 891934 T2222 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 891939 T2222 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 891963 T2222 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 891964 T2222 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369938448051/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty1/
[junit4:junit4] 2> 891964 T2222 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1936982
[junit4:junit4] 2> 891965 T2222 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 891966 T2222 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty1
[junit4:junit4] 2> 891966 T2222 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty1/index/
[junit4:junit4] 2> 891966 T2222 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 891968 T2222 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty1/index
[junit4:junit4] 2> 891971 T2222 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@60ea0db0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79a275f2),segFN=segments_1,generation=1}
[junit4:junit4] 2> 891972 T2222 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 891975 T2222 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 891975 T2222 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 891976 T2222 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 891977 T2222 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 891977 T2222 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 891978 T2222 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 891978 T2222 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 891979 T2222 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 891979 T2222 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 891996 T2222 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 892003 T2222 oass.SolrIndexSearcher.<init> Opening Searcher@28ce09c7 main
[junit4:junit4] 2> 892003 T2222 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty1/tlog
[junit4:junit4] 2> 892005 T2222 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 892006 T2222 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 892010 T2223 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@28ce09c7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 892012 T2222 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 892012 T2222 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 892579 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 892580 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[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:53902_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53902"}
[junit4:junit4] 2> 892580 T2202 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 892580 T2202 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 892619 T2201 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> 892619 T2208 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> 892619 T2221 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> 893042 T2222 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 893042 T2222 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53902 collection:collection1 shard:shard1
[junit4:junit4] 2> 893043 T2222 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 893060 T2222 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 893069 T2222 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 893069 T2222 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 893070 T2222 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53902/collection1/
[junit4:junit4] 2> 893070 T2222 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 893070 T2222 oasc.SyncStrategy.syncToMe http://127.0.0.1:53902/collection1/ has no replicas
[junit4:junit4] 2> 893070 T2222 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53902/collection1/
[junit4:junit4] 2> 893071 T2222 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 894123 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 894143 T2201 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> 894143 T2221 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> 894143 T2208 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> 894154 T2222 oasc.ZkController.register We are http://127.0.0.1:53902/collection1/ and leader is http://127.0.0.1:53902/collection1/
[junit4:junit4] 2> 894154 T2222 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53902
[junit4:junit4] 2> 894154 T2222 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 894154 T2222 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 894155 T2222 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 894156 T2222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 894157 T2179 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 894158 T2179 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 894159 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 894435 T2179 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 894438 T2179 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:53905
[junit4:junit4] 2> 894439 T2179 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 894440 T2179 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 894440 T2179 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369938452590
[junit4:junit4] 2> 894441 T2179 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369938452590/solr.xml
[junit4:junit4] 2> 894441 T2179 oasc.CoreContainer.<init> New CoreContainer 444463451
[junit4:junit4] 2> 894442 T2179 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369938452590/'
[junit4:junit4] 2> 894443 T2179 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369938452590/'
[junit4:junit4] 2> 894571 T2179 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 894572 T2179 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 894572 T2179 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 894573 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 894574 T2179 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 894574 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 894575 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 894575 T2179 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 894576 T2179 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 894576 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 894592 T2179 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 894593 T2179 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53894/solr
[junit4:junit4] 2> 894593 T2179 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 894594 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 894597 T2235 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@310879fe name:ZooKeeperConnection Watcher:127.0.0.1:53894 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 894598 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 894612 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 894623 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 894625 T2237 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5219256c name:ZooKeeperConnection Watcher:127.0.0.1:53894/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 894626 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 894638 T2179 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 895641 T2179 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53905_
[junit4:junit4] 2> 895643 T2179 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53905_
[junit4:junit4] 2> 895646 T2208 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> 895646 T2221 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> 895646 T2237 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 895646 T2201 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 895647 T2201 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> 895647 T2208 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 895648 T2221 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 895654 T2238 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369938452590/collection1
[junit4:junit4] 2> 895654 T2238 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 895655 T2238 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 895655 T2238 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 895656 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 895657 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[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:53902_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53902"}
[junit4:junit4] 2> 895657 T2238 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369938452590/collection1/'
[junit4:junit4] 2> 895658 T2238 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1369938452590/collection1/lib/README' to classloader
[junit4:junit4] 2> 895659 T2238 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1369938452590/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 895669 T2237 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> 895669 T2221 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> 895669 T2208 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> 895669 T2201 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> 895711 T2238 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 895772 T2238 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 895874 T2238 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 895879 T2238 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 896457 T2238 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 896462 T2238 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 896464 T2238 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 896469 T2238 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 896493 T2238 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 896493 T2238 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369938452590/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty2/
[junit4:junit4] 2> 896494 T2238 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1936982
[junit4:junit4] 2> 896494 T2238 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 896496 T2238 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty2
[junit4:junit4] 2> 896496 T2238 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty2/index/
[junit4:junit4] 2> 896496 T2238 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 896497 T2238 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty2/index
[junit4:junit4] 2> 896501 T2238 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b806051 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c09136),segFN=segments_1,generation=1}
[junit4:junit4] 2> 896501 T2238 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 896504 T2238 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 896505 T2238 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 896506 T2238 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 896506 T2238 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 896507 T2238 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 896507 T2238 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 896508 T2238 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 896508 T2238 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 896509 T2238 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 896525 T2238 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 896533 T2238 oass.SolrIndexSearcher.<init> Opening Searcher@1ec602c4 main
[junit4:junit4] 2> 896533 T2238 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty2/tlog
[junit4:junit4] 2> 896534 T2238 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 896535 T2238 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 896539 T2239 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ec602c4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 896542 T2238 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 896542 T2238 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 897173 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 897174 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:53905_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53905"}
[junit4:junit4] 2> 897174 T2202 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 897174 T2202 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 897214 T2201 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> 897214 T2208 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> 897214 T2221 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> 897214 T2237 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> 897548 T2238 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 897548 T2238 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53905 collection:collection1 shard:shard2
[junit4:junit4] 2> 897549 T2238 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 897564 T2238 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 897567 T2238 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 897567 T2238 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 897567 T2238 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53905/collection1/
[junit4:junit4] 2> 897568 T2238 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 897568 T2238 oasc.SyncStrategy.syncToMe http://127.0.0.1:53905/collection1/ has no replicas
[junit4:junit4] 2> 897568 T2238 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53905/collection1/
[junit4:junit4] 2> 897569 T2238 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 898718 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 898741 T2201 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> 898741 T2208 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> 898741 T2221 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> 898741 T2237 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> 898752 T2238 oasc.ZkController.register We are http://127.0.0.1:53905/collection1/ and leader is http://127.0.0.1:53905/collection1/
[junit4:junit4] 2> 898752 T2238 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53905
[junit4:junit4] 2> 898752 T2238 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 898752 T2238 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 898753 T2238 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 898754 T2238 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 898755 T2179 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 898756 T2179 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 898757 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 899034 T2179 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 899038 T2179 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:53908
[junit4:junit4] 2> 899038 T2179 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 899039 T2179 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 899040 T2179 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369938457189
[junit4:junit4] 2> 899040 T2179 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369938457189/solr.xml
[junit4:junit4] 2> 899041 T2179 oasc.CoreContainer.<init> New CoreContainer 869297158
[junit4:junit4] 2> 899041 T2179 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369938457189/'
[junit4:junit4] 2> 899042 T2179 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369938457189/'
[junit4:junit4] 2> 899187 T2179 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 899188 T2179 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 899189 T2179 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 899189 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 899190 T2179 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 899191 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 899191 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 899192 T2179 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 899192 T2179 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 899193 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 899209 T2179 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 899209 T2179 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53894/solr
[junit4:junit4] 2> 899210 T2179 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 899211 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 899214 T2251 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f6064da name:ZooKeeperConnection Watcher:127.0.0.1:53894 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 899215 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 899230 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 899242 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 899245 T2253 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@54049517 name:ZooKeeperConnection Watcher:127.0.0.1:53894/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 899245 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 899254 T2179 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 900247 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 900248 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:53905_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53905"}
[junit4:junit4] 2> 900262 T2201 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> 900262 T2179 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53908_
[junit4:junit4] 2> 900262 T2221 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> 900262 T2237 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> 900262 T2208 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> 900262 T2253 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> 900268 T2179 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53908_
[junit4:junit4] 2> 900271 T2253 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> 900271 T2208 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> 900271 T2221 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> 900271 T2237 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 900271 T2201 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 900272 T2237 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> 900272 T2253 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 900272 T2201 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> 900278 T2208 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 900278 T2221 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 900284 T2254 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369938457189/collection1
[junit4:junit4] 2> 900284 T2254 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 900285 T2254 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 900285 T2254 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 900286 T2254 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369938457189/collection1/'
[junit4:junit4] 2> 900288 T2254 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1369938457189/collection1/lib/README' to classloader
[junit4:junit4] 2> 900288 T2254 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1369938457189/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 900340 T2254 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 900401 T2254 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 900503 T2254 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 900508 T2254 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 901083 T2254 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 901087 T2254 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 901090 T2254 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 901095 T2254 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 901118 T2254 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 901119 T2254 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369938457189/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty3/
[junit4:junit4] 2> 901119 T2254 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1936982
[junit4:junit4] 2> 901120 T2254 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 901121 T2254 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty3
[junit4:junit4] 2> 901121 T2254 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty3/index/
[junit4:junit4] 2> 901121 T2254 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 901122 T2254 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty3/index
[junit4:junit4] 2> 901126 T2254 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6ecc321 lockFactory=org.apache.lucene.store.NativeFSLockFactory@539e152a),segFN=segments_1,generation=1}
[junit4:junit4] 2> 901126 T2254 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 901130 T2254 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 901130 T2254 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 901131 T2254 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 901132 T2254 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 901132 T2254 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 901133 T2254 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 901133 T2254 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 901134 T2254 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 901134 T2254 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 901151 T2254 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 901158 T2254 oass.SolrIndexSearcher.<init> Opening Searcher@e18eea6 main
[junit4:junit4] 2> 901159 T2254 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty3/tlog
[junit4:junit4] 2> 901160 T2254 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 901160 T2254 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 901165 T2255 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e18eea6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 901167 T2254 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 901167 T2254 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 901772 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 901773 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:53908_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53908"}
[junit4:junit4] 2> 901773 T2202 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 901774 T2202 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 901796 T2201 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> 901796 T2208 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> 901796 T2221 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> 901796 T2237 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> 901796 T2253 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> 902171 T2254 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 902171 T2254 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53908 collection:collection1 shard:shard1
[junit4:junit4] 2> 902175 T2254 oasc.ZkController.register We are http://127.0.0.1:53908/collection1/ and leader is http://127.0.0.1:53902/collection1/
[junit4:junit4] 2> 902175 T2254 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53908
[junit4:junit4] 2> 902176 T2254 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 902176 T2254 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C475 name=collection1 org.apache.solr.core.SolrCore@5ea5bb58 url=http://127.0.0.1:53908/collection1 node=127.0.0.1:53908_ C475_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53908_, base_url=http://127.0.0.1:53908}
[junit4:junit4] 2> 902176 T2256 C475 P53908 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 902177 T2254 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 902178 T2256 C475 P53908 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 902178 T2256 C475 P53908 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 902178 T2256 C475 P53908 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 902179 T2179 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 902179 T2179 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 902180 T2256 C475 P53908 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 902180 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 902205 T2211 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 902466 T2179 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 902469 T2179 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:53912
[junit4:junit4] 2> 902470 T2179 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 902471 T2179 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 902471 T2179 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369938460619
[junit4:junit4] 2> 902472 T2179 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369938460619/solr.xml
[junit4:junit4] 2> 902472 T2179 oasc.CoreContainer.<init> New CoreContainer 182395742
[junit4:junit4] 2> 902473 T2179 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369938460619/'
[junit4:junit4] 2> 902473 T2179 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369938460619/'
[junit4:junit4] 2> 902606 T2179 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 902607 T2179 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 902607 T2179 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 902608 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 902608 T2179 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 902609 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 902609 T2179 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 902610 T2179 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 902610 T2179 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 902611 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 902627 T2179 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 902628 T2179 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53894/solr
[junit4:junit4] 2> 902628 T2179 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 902630 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 902633 T2268 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6b7d435c name:ZooKeeperConnection Watcher:127.0.0.1:53894 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 902634 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 902649 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 902661 T2179 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 902663 T2270 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@417f8c15 name:ZooKeeperConnection Watcher:127.0.0.1:53894/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 902664 T2179 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 902675 T2179 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 903300 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 903301 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:53908_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53908"}
[junit4:junit4] 2> 903343 T2201 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> 903343 T2253 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> 903343 T2237 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> 903343 T2208 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> 903343 T2270 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> 903343 T2221 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> 903678 T2179 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53912_
[junit4:junit4] 2> 903680 T2179 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53912_
[junit4:junit4] 2> 903682 T2270 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> 903682 T2221 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> 903682 T2253 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> 903682 T2208 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> 903682 T2237 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 903682 T2201 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 903684 T2270 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 903684 T2201 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> 903683 T2237 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> 903694 T2221 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 903694 T2253 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 903695 T2208 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 903700 T2271 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369938460619/collection1
[junit4:junit4] 2> 903700 T2271 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 903701 T2271 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 903701 T2271 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 903703 T2271 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369938460619/collection1/'
[junit4:junit4] 2> 903704 T2271 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1369938460619/collection1/lib/README' to classloader
[junit4:junit4] 2> 903705 T2271 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1369938460619/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 903757 T2271 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 903818 T2271 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 903920 T2271 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 903926 T2271 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 904208 T2211 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 904208 T2211 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:53908_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 904503 T2271 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 904507 T2271 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 904509 T2271 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 904514 T2271 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 904538 T2271 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 904539 T2271 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369938460619/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty4/
[junit4:junit4] 2> 904539 T2271 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1936982
[junit4:junit4] 2> 904540 T2271 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 904540 T2271 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty4
[junit4:junit4] 2> 904541 T2271 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty4/index/
[junit4:junit4] 2> 904541 T2271 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 904542 T2271 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty4/index
[junit4:junit4] 2> 904546 T2271 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@34a9ae6c lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c043e11),segFN=segments_1,generation=1}
[junit4:junit4] 2> 904547 T2271 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 904550 T2271 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 904551 T2271 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 904551 T2271 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 904552 T2271 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 904553 T2271 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 904553 T2271 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 904554 T2271 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 904554 T2271 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 904555 T2271 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 904571 T2271 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 904579 T2271 oass.SolrIndexSearcher.<init> Opening Searcher@4dd72cbf main
[junit4:junit4] 2> 904580 T2271 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty4/tlog
[junit4:junit4] 2> 904581 T2271 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 904581 T2271 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 904586 T2272 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4dd72cbf main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 904588 T2271 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 904588 T2271 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 904847 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 904848 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:53912_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53912"}
[junit4:junit4] 2> 904848 T2202 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 904848 T2202 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 904856 T2201 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> 904856 T2208 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> 904856 T2221 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> 904856 T2237 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> 904856 T2253 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> 904856 T2270 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> 905592 T2271 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 905592 T2271 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53912 collection:collection1 shard:shard2
[junit4:junit4] 2> 905595 T2271 oasc.ZkController.register We are http://127.0.0.1:53912/collection1/ and leader is http://127.0.0.1:53905/collection1/
[junit4:junit4] 2> 905596 T2271 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53912
[junit4:junit4] 2> 905596 T2271 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 905596 T2271 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C476 name=collection1 org.apache.solr.core.SolrCore@58665334 url=http://127.0.0.1:53912/collection1 node=127.0.0.1:53912_ C476_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53912_, base_url=http://127.0.0.1:53912}
[junit4:junit4] 2> 905597 T2273 C476 P53912 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 905597 T2271 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 905598 T2273 C476 P53912 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 905598 T2273 C476 P53912 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 905599 T2273 C476 P53912 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 905599 T2179 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 905600 T2179 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 905600 T2273 C476 P53912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 905600 T2179 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 905620 T2179 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 905622 T2227 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 905622 T2179 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 905623 T2179 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 905624 T2179 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C477 name=collection1 org.apache.solr.core.SolrCore@5ea5bb58 url=http://127.0.0.1:53908/collection1 node=127.0.0.1:53908_ C477_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53908_, base_url=http://127.0.0.1:53908}
[junit4:junit4] 2> 906210 T2256 C477 P53908 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53902/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 906210 T2256 C477 P53908 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53908 START replicas=[http://127.0.0.1:53902/collection1/] nUpdates=100
[junit4:junit4] 2> 906211 T2256 C477 P53908 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 906212 T2256 C477 P53908 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 906212 T2256 C477 P53908 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 906212 T2256 C477 P53908 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 906212 T2256 C477 P53908 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 906213 T2256 C477 P53908 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53902/collection1/. core=collection1
[junit4:junit4] 2> 906213 T2256 C477 P53908 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C478 name=collection1 org.apache.solr.core.SolrCore@4d63b3e0 url=http://127.0.0.1:53902/collection1 node=127.0.0.1:53902_ C478_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53902_, base_url=http://127.0.0.1:53902, leader=true}
[junit4:junit4] 2> 906220 T2212 C478 P53902 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> 906226 T2213 C478 P53902 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 906229 T2213 C478 P53902 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@60ea0db0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79a275f2),segFN=segments_1,generation=1}
[junit4:junit4] 2> 906230 T2213 C478 P53902 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 906231 T2213 C478 P53902 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@60ea0db0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79a275f2),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@60ea0db0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79a275f2),segFN=segments_2,generation=2}
[junit4:junit4] 2> 906231 T2213 C478 P53902 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 906232 T2213 C478 P53902 oass.SolrIndexSearcher.<init> Opening Searcher@5f5562fb realtime
[junit4:junit4] 2> 906232 T2213 C478 P53902 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 906233 T2213 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 906234 T2256 C477 P53908 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 906234 T2256 C477 P53908 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 906236 T2214 C478 P53902 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 906237 T2214 C478 P53902 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 906238 T2256 C477 P53908 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 906238 T2256 C477 P53908 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 906238 T2256 C477 P53908 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 906240 T2214 C478 P53902 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> 906241 T2256 C477 P53908 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 906243 T2256 C477 P53908 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty3/index.20130530132744658
[junit4:junit4] 2> 906243 T2256 C477 P53908 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@27887a7f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a54008) fullCopy=false
[junit4:junit4] 2> 906246 T2214 C478 P53902 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> 906248 T2256 C477 P53908 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 906249 T2256 C477 P53908 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 906249 T2256 C477 P53908 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 906251 T2256 C477 P53908 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6ecc321 lockFactory=org.apache.lucene.store.NativeFSLockFactory@539e152a),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6ecc321 lockFactory=org.apache.lucene.store.NativeFSLockFactory@539e152a),segFN=segments_2,generation=2}
[junit4:junit4] 2> 906252 T2256 C477 P53908 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 906252 T2256 C477 P53908 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 906252 T2256 C477 P53908 oass.SolrIndexSearcher.<init> Opening Searcher@5c7c4a38 main
[junit4:junit4] 2> 906254 T2255 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c7c4a38 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 906254 T2256 C477 P53908 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty3/index.20130530132744658 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty3/index.20130530132744658;done=true>>]
[junit4:junit4] 2> 906255 T2256 C477 P53908 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty3/index.20130530132744658
[junit4:junit4] 2> 906255 T2256 C477 P53908 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty3/index.20130530132744658
[junit4:junit4] 2> 906255 T2256 C477 P53908 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 906255 T2256 C477 P53908 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 906256 T2256 C477 P53908 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 906256 T2256 C477 P53908 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 906262 T2256 C477 P53908 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 906361 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 906362 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:53912_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53912"}
[junit4:junit4] 2> 906366 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:53908_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53908"}
[junit4:junit4] 2> 906444 T2201 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> 906444 T2208 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> 906444 T2253 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> 906444 T2221 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> 906444 T2237 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> 906444 T2270 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> 906624 T2227 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 906624 T2227 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:53912_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 906626 T2179 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 907628 T2179 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C476_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53912_, base_url=http://127.0.0.1:53912}
[junit4:junit4] 2> 908627 T2273 C476 P53912 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53905/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 908627 T2273 C476 P53912 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53912 START replicas=[http://127.0.0.1:53905/collection1/] nUpdates=100
[junit4:junit4] 2> 908628 T2273 C476 P53912 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 908628 T2273 C476 P53912 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 908628 T2273 C476 P53912 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 908628 T2273 C476 P53912 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 908628 T2273 C476 P53912 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 908629 T2273 C476 P53912 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53905/collection1/. core=collection1
[junit4:junit4] 2> 908629 T2273 C476 P53912 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 908630 T2179 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C479 name=collection1 org.apache.solr.core.SolrCore@316cefc3 url=http://127.0.0.1:53905/collection1 node=127.0.0.1:53905_ C479_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53905_, base_url=http://127.0.0.1:53905, leader=true}
[junit4:junit4] 2> 908637 T2228 C479 P53905 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> 908641 T2229 C479 P53905 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 908644 T2229 C479 P53905 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b806051 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c09136),segFN=segments_1,generation=1}
[junit4:junit4] 2> 908645 T2229 C479 P53905 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 908646 T2229 C479 P53905 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b806051 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c09136),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b806051 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c09136),segFN=segments_2,generation=2}
[junit4:junit4] 2> 908646 T2229 C479 P53905 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 908647 T2229 C479 P53905 oass.SolrIndexSearcher.<init> Opening Searcher@6776a3f8 realtime
[junit4:junit4] 2> 908647 T2229 C479 P53905 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 908648 T2229 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 908649 T2273 C476 P53912 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 908649 T2273 C476 P53912 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 908651 T2230 C479 P53905 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 908652 T2230 C479 P53905 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 908652 T2273 C476 P53912 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 908653 T2273 C476 P53912 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 908653 T2273 C476 P53912 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 908655 T2230 C479 P53905 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> 908656 T2273 C476 P53912 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 908657 T2273 C476 P53912 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty4/index.20130530132747072
[junit4:junit4] 2> 908658 T2273 C476 P53912 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@23c3f708 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2cd41185) fullCopy=false
[junit4:junit4] 2> 908660 T2230 C479 P53905 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> 908661 T2273 C476 P53912 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 908663 T2273 C476 P53912 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 908663 T2273 C476 P53912 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 908665 T2273 C476 P53912 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@34a9ae6c lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c043e11),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@34a9ae6c lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c043e11),segFN=segments_2,generation=2}
[junit4:junit4] 2> 908666 T2273 C476 P53912 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 908666 T2273 C476 P53912 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 908666 T2273 C476 P53912 oass.SolrIndexSearcher.<init> Opening Searcher@4de2eb84 main
[junit4:junit4] 2> 908667 T2272 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4de2eb84 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 908668 T2273 C476 P53912 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty4/index.20130530132747072 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty4/index.20130530132747072;done=true>>]
[junit4:junit4] 2> 908668 T2273 C476 P53912 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty4/index.20130530132747072
[junit4:junit4] 2> 908669 T2273 C476 P53912 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1369938443875/jetty4/index.20130530132747072
[junit4:junit4] 2> 908669 T2273 C476 P53912 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 908669 T2273 C476 P53912 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 908669 T2273 C476 P53912 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 908669 T2273 C476 P53912 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 908671 T2273 C476 P53912 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 909516 T2202 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 909517 T2202 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:53912_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53912"}
[junit4:junit4] 2> 909532 T2201 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> 909532 T2237 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> 909532 T2208 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> 909532 T2253 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> 909532 T2221 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> 909532 T2270 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> 909632 T2179 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 909633 T2179 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C480 name=collection1 org.apache.solr.core.SolrCore@7b45c9fb url=http://127.0.0.1:53897/collection1 node=127.0.0.1:53897_ C480_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:53897_, base_url=http://127.0.0.1:53897, leader=true}
[junit4:junit4] 2> 909642 T2191 C480 P53897 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 909646 T2191 C480 P53897 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7656840 lockFactory=org.apache.lucene.store.NativeFSLockFactory@72570967),segFN=segments_1,generation=1}
[junit4:junit4] 2> 909647 T2191 C480 P53897 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 909648 T2191 C480 P53897 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7656840 lockFactory=org.apache.lucene.store.NativeFSLockFactory@72570967),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7656840 lockFactory=org.apache.lucene.store.NativeFSLockFactory@72570967),segFN=segments_2,generation=2}
[junit4:junit4] 2> 909648 T2191 C480 P53897 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 909649 T2191 C480 P53897 oass.SolrIndexSearcher.<init> Opening Searcher@502f2b26 main
[junit4:junit4] 2> 909650 T2191 C480 P53897 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 909650 T2205 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@502f2b26 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 909651 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 909662 T2215 C478 P53902 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 909664 T2215 C478 P53902 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@60ea0db0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79a275f2),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@60ea0db0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79a275f2),segFN=segments_3,generation=3}
[junit4:junit4] 2> 909664 T2215 C478 P53902 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 909665 T2215 C478 P53902 oass.SolrIndexSearcher.<init> Opening Searcher@14ce4d17 main
[junit4:junit4] 2> 909665 T2215 C478 P53902 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 909666 T2223 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14ce4d17 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 909667 T2215 C478 P53902 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:53908/collection1/, StdNode: http://127.0.0.1:53905/collection1/, StdNode: http://127.0.0.1:53912/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 909670 T2231 C479 P53905 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 909673 T2231 C479 P53905 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b806051 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c09136),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b806051 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c09136),segFN=segments_3,generation=3}
[junit4:junit4] 2> 909673 T2231 C479 P53905 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 909674 T2231 C479 P53905 oass.SolrIndexSearcher.<init> Opening Searcher@41331925 main
[junit4:junit4] 2> 909674 T2231 C479 P53905 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 909675 T2239 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@41331925 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 909676 T2231 C479 P53905 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> C477_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53908_, base_url=http://127.0.0.1:53908}
[junit4:junit4] 2> 909678 T2243 C477 P53908 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C476_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53912_, base_url=http://127.0.0.1:53912}
[junit4:junit4] 2> 909678 T2260 C476 P53912 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 909679 T2243 C477 P53908 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6ecc321 lockFactory=org.apache.lucene.store.NativeFSLockFactory@539e152a),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6ecc321 lockFactory=org.apache.lucene.store.NativeFSLockFactory@539e152a),segFN=segments_3,generation=3}
[junit4:junit4] 2> 909680 T2260 C476 P53912 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@34a9ae6c lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c043e11),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@34a9ae6c lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c043e11),segFN=segments_3,generation=3}
[junit4:junit4] 2> 909681 T2243 C477 P53908 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 909681 T2260 C476 P53912 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 909682 T2243 C477 P53908 oass.SolrIndexSearcher.<init> Opening Searcher@6b4e9070 main
[junit4:junit4] 2> 909683 T2260 C476 P53912 oass.SolrIndexSearcher.<init> Opening Searcher@45c0d386 main
[junit4:junit4] 2> 909683 T2243 C477 P53908 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 909684 T2255 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6b4e9070 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 909683 T2260 C476 P53912 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 909684 T2243 C477 P53908 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> 909684 T2272 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@45c0d386 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 909685 T2260 C476 P53912 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 7
[junit4:junit4] 2> 909686 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> 909687 T2179 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 909690 T2216 C478 P53902 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> 909693 T2244 C477 P53908 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> 909695 T2232 C479 P53905 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> 909697 T2261 C476 P53912 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> 911702 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436484601241403392)} 0 2
[junit4:junit4] 2> 911711 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436484601245597696&update.from=http://127.0.0.1:53905/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436484601245597696)} 0 1
[junit4:junit4] 2> 911715 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436484601250840576&update.from=http://127.0.0.1:53902/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436484601250840576)} 0 1
[junit4:junit4] 2> 911716 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1436484601250840576)} 0 6
[junit4:junit4] 2> 911717 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436484601245597696)} 0 12
[junit4:junit4] 2> 911722 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1436484601262374912)]} 0 1
[junit4:junit4] 2> 911734 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1436484601270763520)]} 0 1
[junit4:junit4] 2> 911734 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1436484601270763520)]} 0 5
[junit4:junit4] 2> 911735 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0]} 0 9
[junit4:junit4] 2> 911740 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1436484601281249280)]} 0 1
[junit4:junit4] 2> 911752 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1436484601289637888)]} 0 1
[junit4:junit4] 2> 911752 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!1 (1436484601289637888)]} 0 5
[junit4:junit4] 2> 911753 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1]} 0 10
[junit4:junit4] 2> 911757 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1436484601300123648)]} 0 0
[junit4:junit4] 2> 911769 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1436484601307463680)]} 0 1
[junit4:junit4] 2> 911769 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!2 (1436484601307463680)]} 0 5
[junit4:junit4] 2> 911770 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2]} 0 9
[junit4:junit4] 2> 911774 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1436484601316900864)]} 0 1
[junit4:junit4] 2> 911783 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1436484601323192320)]} 0 1
[junit4:junit4] 2> 911783 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1436484601323192320)]} 0 4
[junit4:junit4] 2> 911784 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3]} 0 8
[junit4:junit4] 2> 911788 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1436484601331580928)]} 0 1
[junit4:junit4] 2> 911795 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1436484601335775232)]} 0 1
[junit4:junit4] 2> 911795 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1436484601335775232)]} 0 4
[junit4:junit4] 2> 911800 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1436484601344163840)]} 0 1
[junit4:junit4] 2> 911806 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1436484601347309568)]} 0 1
[junit4:junit4] 2> 911806 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1436484601347309568)]} 0 4
[junit4:junit4] 2> 911810 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1436484601354649600)]} 0 1
[junit4:junit4] 2> 911816 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1436484601357795328)]} 0 1
[junit4:junit4] 2> 911816 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1436484601357795328)]} 0 4
[junit4:junit4] 2> 911819 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1436484601365135360)]} 0 0
[junit4:junit4] 2> 911829 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1436484601372475392)]} 0 0
[junit4:junit4] 2> 911830 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1436484601372475392)]} 0 4
[junit4:junit4] 2> 911831 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7]} 0 8
[junit4:junit4] 2> 911834 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1436484601380864000)]} 0 0
[junit4:junit4] 2> 911845 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1436484601387155456)]} 0 1
[junit4:junit4] 2> 911845 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!8 (1436484601387155456)]} 0 5
[junit4:junit4] 2> 911846 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8]} 0 9
[junit4:junit4] 2> 911849 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1436484601396592640)]} 0 0
[junit4:junit4] 2> 911857 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1436484601399738368)]} 0 1
[junit4:junit4] 2> 911857 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1436484601399738368)]} 0 5
[junit4:junit4] 2> 911860 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1436484601408126976)]} 0 0
[junit4:junit4] 2> 911867 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1436484601411272704)]} 0 1
[junit4:junit4] 2> 911867 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1436484601411272704)]} 0 4
[junit4:junit4] 2> 911872 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1436484601419661312)]} 0 0
[junit4:junit4] 2> 911878 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1436484601422807040)]} 0 1
[junit4:junit4] 2> 911878 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1436484601422807040)]} 0 4
[junit4:junit4] 2> 911882 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1436484601430147072)]} 0 1
[junit4:junit4] 2> 911888 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1436484601434341376)]} 0 0
[junit4:junit4] 2> 911889 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1436484601434341376)]} 0 4
[junit4:junit4] 2> 911894 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1436484601442729984)]} 0 1
[junit4:junit4] 2> 911903 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1436484601449021440)]} 0 1
[junit4:junit4] 2> 911903 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1436484601449021440)]} 0 4
[junit4:junit4] 2> 911904 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13]} 0 8
[junit4:junit4] 2> 911909 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1436484601458458624)]} 0 1
[junit4:junit4] 2> 911918 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1436484601464750080)]} 0 1
[junit4:junit4] 2> 911918 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1436484601464750080)]} 0 4
[junit4:junit4] 2> 911919 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14]} 0 8
[junit4:junit4] 2> 911924 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1436484601474187264)]} 0 1
[junit4:junit4] 2> 911931 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1436484601477332992)]} 0 1
[junit4:junit4] 2> 911931 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1436484601477332992)]} 0 5
[junit4:junit4] 2> 911935 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1436484601485721600)]} 0 1
[junit4:junit4] 2> 911942 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1436484601488867328)]} 0 1
[junit4:junit4] 2> 911942 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1436484601488867328)]} 0 5
[junit4:junit4] 2> 911945 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1436484601497255936)]} 0 0
[junit4:junit4] 2> 911953 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1436484601501450240)]} 0 1
[junit4:junit4] 2> 911953 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1436484601501450240)]} 0 4
[junit4:junit4] 2> 911958 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1436484601509838848)]} 0 1
[junit4:junit4] 2> 911967 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1436484601516130304)]} 0 1
[junit4:junit4] 2> 911967 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!18 (1436484601516130304)]} 0 4
[junit4:junit4] 2> 911968 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18]} 0 8
[junit4:junit4] 2> 911973 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1436484601525567488)]} 0 1
[junit4:junit4] 2> 911982 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1436484601531858944)]} 0 1
[junit4:junit4] 2> 911982 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!19 (1436484601531858944)]} 0 4
[junit4:junit4] 2> 911983 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19]} 0 8
[junit4:junit4] 2> 911987 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1436484601540247552)]} 0 1
[junit4:junit4] 2> 911996 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1436484601547587584)]} 0 0
[junit4:junit4] 2> 911997 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!20 (1436484601547587584)]} 0 4
[junit4:junit4] 2> 911998 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20]} 0 8
[junit4:junit4] 2> 912002 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1436484601555976192)]} 0 1
[junit4:junit4] 2> 912008 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1436484601559121920)]} 0 1
[junit4:junit4] 2> 912008 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1436484601559121920)]} 0 4
[junit4:junit4] 2> 912012 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1436484601566461952)]} 0 1
[junit4:junit4] 2> 912019 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1436484601570656256)]} 0 1
[junit4:junit4] 2> 912019 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1436484601570656256)]} 0 4
[junit4:junit4] 2> 912023 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1436484601579044864)]} 0 1
[junit4:junit4] 2> 912030 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1436484601582190592)]} 0 1
[junit4:junit4] 2> 912031 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1436484601582190592)]} 0 5
[junit4:junit4] 2> 912035 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1436484601590579200)]} 0 1
[junit4:junit4] 2> 912041 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1436484601594773504)]} 0 0
[junit4:junit4] 2> 912042 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1436484601594773504)]} 0 4
[junit4:junit4] 2> 912047 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1436484601603162112)]} 0 1
[junit4:junit4] 2> 912057 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1436484601610502144)]} 0 1
[junit4:junit4] 2> 912057 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1436484601610502144)]} 0 4
[junit4:junit4] 2> 912058 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25]} 0 8
[junit4:junit4] 2> 912061 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1436484601618890752)]} 0 0
[junit4:junit4] 2> 912070 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1436484601625182208)]} 0 0
[junit4:junit4] 2> 912071 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1436484601625182208)]} 0 4
[junit4:junit4] 2> 912072 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26]} 0 8
[junit4:junit4] 2> 912077 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1436484601634619392)]} 0 1
[junit4:junit4] 2> 912084 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1436484601637765120)]} 0 1
[junit4:junit4] 2> 912084 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1436484601637765120)]} 0 5
[junit4:junit4] 2> 912088 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1436484601646153728)]} 0 0
[junit4:junit4] 2> 912094 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1436484601649299456)]} 0 1
[junit4:junit4] 2> 912094 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1436484601649299456)]} 0 4
[junit4:junit4] 2> 912097 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1436484601656639488)]} 0 0
[junit4:junit4] 2> 912104 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1436484601659785216)]} 0 0
[junit4:junit4] 2> 912105 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1436484601659785216)]} 0 5
[junit4:junit4] 2> 912109 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1436484601668173824)]} 0 1
[junit4:junit4] 2> 912114 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1436484601671319552)]} 0 0
[junit4:junit4] 2> 912115 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1436484601671319552)]} 0 4
[junit4:junit4] 2> 912120 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1436484601679708160)]} 0 1
[junit4:junit4] 2> 912130 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1436484601687048192)]} 0 1
[junit4:junit4] 2> 912130 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1436484601687048192)]} 0 4
[junit4:junit4] 2> 912131 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31]} 0 9
[junit4:junit4] 2> 912135 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1436484601695436800)]} 0 1
[junit4:junit4] 2> 912145 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1436484601702776832)]} 0 1
[junit4:junit4] 2> 912145 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!32 (1436484601702776832)]} 0 4
[junit4:junit4] 2> 912146 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32]} 0 9
[junit4:junit4] 2> 912150 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1436484601712214016)]} 0 0
[junit4:junit4] 2> 912161 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1436484601719554048)]} 0 1
[junit4:junit4] 2> 912161 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!33 (1436484601719554048)]} 0 4
[junit4:junit4] 2> 912162 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33]} 0 8
[junit4:junit4] 2> 912166 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1436484601727942656)]} 0 1
[junit4:junit4] 2> 912171 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1436484601731088384)]} 0 0
[junit4:junit4] 2> 912172 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1436484601731088384)]} 0 4
[junit4:junit4] 2> 912175 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1436484601738428416)]} 0 0
[junit4:junit4] 2> 912186 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1436484601744719872)]} 0 1
[junit4:junit4] 2> 912186 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!35 (1436484601744719872)]} 0 5
[junit4:junit4] 2> 912187 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35]} 0 9
[junit4:junit4] 2> 912190 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1436484601754157056)]} 0 0
[junit4:junit4] 2> 912197 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1436484601757302784)]} 0 1
[junit4:junit4] 2> 912197 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1436484601757302784)]} 0 4
[junit4:junit4] 2> 912201 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1436484601765691392)]} 0 0
[junit4:junit4] 2> 912211 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1436484601771982848)]} 0 1
[junit4:junit4] 2> 912211 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1436484601771982848)]} 0 4
[junit4:junit4] 2> 912212 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37]} 0 8
[junit4:junit4] 2> 912216 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1436484601780371456)]} 0 1
[junit4:junit4] 2> 912224 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1436484601785614336)]} 0 0
[junit4:junit4] 2> 912225 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1436484601785614336)]} 0 5
[junit4:junit4] 2> 912226 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38]} 0 8
[junit4:junit4] 2> 912231 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1436484601796100096)]} 0 1
[junit4:junit4] 2> 912239 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1436484601800294400)]} 0 1
[junit4:junit4] 2> 912239 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1436484601800294400)]} 0 5
[junit4:junit4] 2> 912243 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1436484601808683008)]} 0 1
[junit4:junit4] 2> 912250 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1436484601811828736)]} 0 1
[junit4:junit4] 2> 912250 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1436484601811828736)]} 0 5
[junit4:junit4] 2> 912254 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1436484601820217344)]} 0 1
[junit4:junit4] 2> 912262 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1436484601826508800)]} 0 0
[junit4:junit4] 2> 912263 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1436484601826508800)]} 0 4
[junit4:junit4] 2> 912264 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41]} 0 8
[junit4:junit4] 2> 912268 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1436484601834897408)]} 0 1
[junit4:junit4] 2> 912277 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1436484601841188864)]} 0 1
[junit4:junit4] 2> 912277 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1436484601841188864)]} 0 4
[junit4:junit4] 2> 912278 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42]} 0 8
[junit4:junit4] 2> 912283 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1436484601850626048)]} 0 1
[junit4:junit4] 2> 912289 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1436484601853771776)]} 0 1
[junit4:junit4] 2> 912289 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1436484601853771776)]} 0 4
[junit4:junit4] 2> 912293 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1436484601861111808)]} 0 1
[junit4:junit4] 2> 912300 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1436484601865306112)]} 0 1
[junit4:junit4] 2> 912300 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1436484601865306112)]} 0 4
[junit4:junit4] 2> 912303 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1436484601872646144)]} 0 0
[junit4:junit4] 2> 912313 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1436484601878937600)]} 0 1
[junit4:junit4] 2> 912313 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!45 (1436484601878937600)]} 0 4
[junit4:junit4] 2> 912314 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45]} 0 8
[junit4:junit4] 2> 912318 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1436484601887326208)]} 0 1
[junit4:junit4] 2> 912324 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1436484601890471936)]} 0 1
[junit4:junit4] 2> 912324 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1436484601890471936)]} 0 4
[junit4:junit4] 2> 912327 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1436484601897811968)]} 0 0
[junit4:junit4] 2> 912335 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1436484601900957696)]} 0 1
[junit4:junit4] 2> 912335 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1436484601900957696)]} 0 5
[junit4:junit4] 2> 912338 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1436484601909346304)]} 0 0
[junit4:junit4] 2> 912344 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1436484601912492032)]} 0 0
[junit4:junit4] 2> 912345 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1436484601912492032)]} 0 4
[junit4:junit4] 2> 912348 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1436484601919832064)]} 0 0
[junit4:junit4] 2> 912355 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1436484601922977792)]} 0 1
[junit4:junit4] 2> 912355 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1436484601922977792)]} 0 4
[junit4:junit4] 2> 912359 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1436484601930317824)]} 0 1
[junit4:junit4] 2> 912368 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1436484601936609280)]} 0 1
[junit4:junit4] 2> 912368 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!50 (1436484601936609280)]} 0 4
[junit4:junit4] 2> 912369 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50]} 0 8
[junit4:junit4] 2> 912373 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1436484601944997888)]} 0 1
[junit4:junit4] 2> 912379 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1436484601948143616)]} 0 1
[junit4:junit4] 2> 912379 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1436484601948143616)]} 0 4
[junit4:junit4] 2> 912384 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1436484601956532224)]} 0 1
[junit4:junit4] 2> 912391 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1436484601960726528)]} 0 1
[junit4:junit4] 2> 912391 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1436484601960726528)]} 0 4
[junit4:junit4] 2> 912395 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1436484601968066560)]} 0 1
[junit4:junit4] 2> 912400 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1436484601971212288)]} 0 0
[junit4:junit4] 2> 912401 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1436484601971212288)]} 0 4
[junit4:junit4] 2> 912405 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1436484601978552320)]} 0 1
[junit4:junit4] 2> 912411 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1436484601981698048)]} 0 1
[junit4:junit4] 2> 912411 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1436484601981698048)]} 0 4
[junit4:junit4] 2> 912414 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1436484601989038080)]} 0 0
[junit4:junit4] 2> 912424 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1436484601995329536)]} 0 1
[junit4:junit4] 2> 912424 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1436484601995329536)]} 0 4
[junit4:junit4] 2> 912425 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55]} 0 8
[junit4:junit4] 2> 912428 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1436484602003718144)]} 0 0
[junit4:junit4] 2> 912435 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1436484602006863872)]} 0 1
[junit4:junit4] 2> 912435 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1436484602006863872)]} 0 4
[junit4:junit4] 2> 912438 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1436484602014203904)]} 0 0
[junit4:junit4] 2> 912445 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1436484602017349632)]} 0 1
[junit4:junit4] 2> 912445 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1436484602017349632)]} 0 4
[junit4:junit4] 2> 912449 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1436484602024689664)]} 0 1
[junit4:junit4] 2> 912456 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1436484602027835392)]} 0 1
[junit4:junit4] 2> 912456 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1436484602027835392)]} 0 5
[junit4:junit4] 2> 912459 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1436484602036224000)]} 0 0
[junit4:junit4] 2> 912469 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1436484602042515456)]} 0 0
[junit4:junit4] 2> 912470 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!59 (1436484602042515456)]} 0 5
[junit4:junit4] 2> 912471 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59]} 0 9
[junit4:junit4] 2> 912474 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1436484602051952640)]} 0 0
[junit4:junit4] 2> 912484 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1436484602059292672)]} 0 0
[junit4:junit4] 2> 912485 T2217 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!60 (1436484602059292672)]} 0 4
[junit4:junit4] 2> 912486 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60]} 0 8
[junit4:junit4] 2> 912490 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1436484602068729856)]} 0 0
[junit4:junit4] 2> 912499 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1436484602072924160)]} 0 1
[junit4:junit4] 2> 912499 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1436484602072924160)]} 0 5
[junit4:junit4] 2> 912502 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1436484602081312768)]} 0 0
[junit4:junit4] 2> 912510 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1436484602084458496)]} 0 1
[junit4:junit4] 2> 912510 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1436484602084458496)]} 0 5
[junit4:junit4] 2> 912513 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1436484602092847104)]} 0 0
[junit4:junit4] 2> 912520 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1436484602095992832)]} 0 1
[junit4:junit4] 2> 912520 T2233 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1436484602095992832)]} 0 4
[junit4:junit4] 2> 912524 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64 (1436484602103332864)]} 0 1
[junit4:junit4] 2> 912533 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!64 (1436484602109624320)]} 0 1
[junit4:junit4] 2> 912533 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!64 (1436484602109624320)]} 0 4
[junit4:junit4] 2> 912534 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64]} 0 8
[junit4:junit4] 2> 912538 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65 (1436484602118012928)]} 0 1
[junit4:junit4] 2> 912544 T2243 C477 P53908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!65 (1436484602122207232)]} 0 0
[junit4:junit4] 2> 912545 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65 (1436484602122207232)]} 0 4
[junit4:junit4] 2> 912550 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66 (1436484602130595840)]} 0 1
[junit4:junit4] 2> 912558 T2262 C476 P53912 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53905/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!66 (1436484602136887296)]} 0 0
[junit4:junit4] 2> 912559 T2231 C479 P53905 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53902/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!66 (1436484602136887296)]} 0 4
[junit4:junit4] 2> 912560 T2215 C478 P53902 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66]} 0 8
[junit4:junit4] 2> 912564 T2191 C480 P53897 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!67 (1
[...truncated too long message...]
Sync: core=collection1 url=http://127.0.0.1:49068/_swb/v DONE. sync succeeded
[junit4:junit4] 2> 1249272 T2395 oasc.SyncStrategy.syncReplicas We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 2> 1249273 T2395 oasc.ShardLeaderElectionContext.runLeaderProcess Sync was not a success but no one else is active! I am the leader
[junit4:junit4] 2> 1249273 T2395 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49068/_swb/v/collection1/
[junit4:junit4] 2> 1249273 T2395 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@14a62325
[junit4:junit4] 2> 1249274 T2395 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=4,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=805,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 1249275 T2395 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1249275 T2395 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1249276 T2395 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 1249279 T2395 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1249279 T2395 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1249279 T2395 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369938512492/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369938512492/jetty4;done=false>>]
[junit4:junit4] 2> 1249279 T2395 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369938512492/jetty4
[junit4:junit4] 2> 1249280 T2395 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369938512492/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369938512492/jetty4/index;done=false>>]
[junit4:junit4] 2> 1249280 T2395 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369938512492/jetty4/index
[junit4:junit4] 2> 1249280 T2395 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1249281 T2395 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89780290355200012-5-n_0000000001
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:152)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:260)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 1249281 T2395 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1249282 T2395 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> 1249282 T2395 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1249282 T2395 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> 1249282 T2395 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1249283 T2395 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=Memory doPackFST= true), _version_=PostingsFormat(name=TestBloomFilteredLucene41Postings)}, docValues:{}, sim=DefaultSimilarity, locale=es_CO, timezone=America/Monterrey
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=3,free=116635552,total=393216000
[junit4:junit4] 2> NOTE: All tests run in this JVM: [FullSolrCloudDistribCmdsTest, DocumentAnalysisRequestHandlerTest, AnalysisAfterCoreReloadTest, RecoveryZkTest, XmlUpdateRequestHandlerTest, ZkCLITest, TestStressVersions, TestBadConfig, TestMergePolicyConfig, TestPropInject, TestDefaultSearchFieldResource, TimeZoneUtilsTest, TestCopyFieldCollectionResource, TestCloudManagedSchema, TestArbitraryIndexDir, TestSolrCoreProperties, TestLRUCache, TestLFUCache, QueryEqualityTest, TestFieldResource, NotRequiredUniqueKeyTest, SolrIndexConfigTest, TestSolrDeletionPolicy1, TermVectorComponentTest, TestCodecSupport, SynonymTokenizerTest, TestSolrIndexConfig, PluginInfoTest, WordBreakSolrSpellCheckerTest, OverseerTest, PrimitiveFieldTypeTest, TestSchemaNameResource, TestJmxMonitoredMap, TestValueSourceCache, TestGroupingSearch, TestFaceting, ChaosMonkeySafeLeaderTest, TestUniqueKeyFieldResource, BasicZkTest, SpellCheckComponentTest, TestSerializedLuceneMatchVersion, TestRandomFaceting, IndexBasedSpellCheckerTest, FileUtilsTest, ResourceLoaderTest, TestSchemaVersionResource, TestCoreContainer, TestManagedSchema, LoggingHandlerTest, NoCacheHeaderTest, DocumentBuilderTest, TestWordDelimiterFilterFactory, PrimUtilsTest, FieldAnalysisRequestHandlerTest, PingRequestHandlerTest, TestRangeQuery, MoreLikeThisHandlerTest, TestIndexSearcher, QueryResultKeyTest, ChaosMonkeyNothingIsSafeTest, SuggesterTest, RAMDirectoryFactoryTest, PreAnalyzedFieldTest, TermVectorComponentDistributedTest, TestSolrJ, UpdateRequestProcessorFactoryTest, TestFuzzyAnalyzedSuggestions, RequiredFieldsTest, TestQueryTypes, ClusterStateTest, TestTrie, RequestHandlersTest, ShardSplitTest, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 295.61s, 1 test, 1 error <<< FAILURES!
[...truncated 462 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:386: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:366: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:887: There were test failures: 296 suites, 1235 tests, 2 errors, 13 ignored (7 assumptions)
Total time: 51 minutes 10 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure