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/21 03:38:09 UTC
[JENKINS] Lucene-Solr-Tests-trunk-Java7 - Build # 4004 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java7/4004/
2 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:42727/bmn 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:42727/bmn returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([61A9BCC6332F20AE:E04F32DE44704092]: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)
FAILED: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:38319/soly/c 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:38319/soly/c returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([61A9BCC6332F20AE:E04F32DE44704092]: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)
Build Log:
[...truncated 9282 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 243760 T438 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /bmn/
[junit4:junit4] 2> 243766 T438 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1369098663751
[junit4:junit4] 2> 243768 T438 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 243768 T439 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 243869 T438 oasc.ZkTestServer.run start zk server on port:42720
[junit4:junit4] 2> 243870 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 243900 T445 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@31a7cbdd name:ZooKeeperConnection Watcher:127.0.0.1:42720 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 243900 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 243901 T438 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 243912 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 243915 T447 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15130983 name:ZooKeeperConnection Watcher:127.0.0.1:42720/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 243915 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 243915 T438 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 243920 T438 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 243929 T438 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 243932 T438 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 243935 T438 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 243936 T438 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 243947 T438 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 243948 T438 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 244052 T438 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 244053 T438 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 244057 T438 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 244057 T438 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 244065 T438 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 244066 T438 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 244070 T438 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 244071 T438 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 244074 T438 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 244075 T438 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 244078 T438 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 244079 T438 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 244082 T438 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 244083 T438 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 244388 T438 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 244392 T438 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:42723
[junit4:junit4] 2> 244394 T438 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 244395 T438 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 244395 T438 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369098664078
[junit4:junit4] 2> 244396 T438 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369098664078/solr.xml
[junit4:junit4] 2> 244396 T438 oasc.CoreContainer.<init> New CoreContainer 1373074167
[junit4:junit4] 2> 244397 T438 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369098664078/'
[junit4:junit4] 2> 244397 T438 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369098664078/'
[junit4:junit4] 2> 244525 T438 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 244526 T438 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 244526 T438 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 244527 T438 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 244527 T438 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 244528 T438 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 244528 T438 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 244529 T438 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 244529 T438 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 244530 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 244549 T438 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 244549 T438 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42720/solr
[junit4:junit4] 2> 244550 T438 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 244551 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 244554 T458 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@38d5223c name:ZooKeeperConnection Watcher:127.0.0.1:42720 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 244555 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 244557 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 244570 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 244572 T460 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1758827b name:ZooKeeperConnection Watcher:127.0.0.1:42720/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 244573 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 244575 T438 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 244585 T438 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 244589 T438 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 244591 T438 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42723_bmn
[junit4:junit4] 2> 244599 T438 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42723_bmn
[junit4:junit4] 2> 244602 T438 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 244615 T438 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 244618 T438 oasc.Overseer.start Overseer (id=89725250028044291-127.0.0.1:42723_bmn-n_0000000000) starting
[junit4:junit4] 2> 244628 T438 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 244640 T462 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 244641 T438 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 244644 T438 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 244646 T438 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 244649 T461 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 244653 T463 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369098664078/collection1
[junit4:junit4] 2> 244654 T463 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 244654 T463 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 244655 T463 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 244656 T463 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369098664078/collection1/'
[junit4:junit4] 2> 244658 T463 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1369098664078/collection1/lib/README' to classloader
[junit4:junit4] 2> 244658 T463 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1369098664078/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 244712 T463 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 244780 T463 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 244881 T463 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 244888 T463 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 245502 T463 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 245507 T463 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 245509 T463 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 245515 T463 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 245547 T463 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 245548 T463 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369098664078/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369098663751/control/data/
[junit4:junit4] 2> 245548 T463 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@796d470b
[junit4:junit4] 2> 245549 T463 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 245550 T463 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/control/data
[junit4:junit4] 2> 245550 T463 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369098663751/control/data/index/
[junit4:junit4] 2> 245550 T463 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369098663751/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 245551 T463 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/control/data/index
[junit4:junit4] 2> 245557 T463 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4ffb2490 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67d1de8b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 245557 T463 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 245560 T463 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 245561 T463 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 245562 T463 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 245562 T463 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 245563 T463 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 245563 T463 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 245564 T463 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 245564 T463 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 245565 T463 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 245582 T463 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 245590 T463 oass.SolrIndexSearcher.<init> Opening Searcher@290da9f7 main
[junit4:junit4] 2> 245591 T463 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369098663751/control/data/tlog
[junit4:junit4] 2> 245592 T463 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 245593 T463 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 245597 T464 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@290da9f7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 245599 T463 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 245599 T463 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 246153 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 246154 T461 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:42723_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42723/bmn"}
[junit4:junit4] 2> 246154 T461 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 246155 T461 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 246171 T460 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> 246631 T463 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 246631 T463 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42723/bmn collection:control_collection shard:shard1
[junit4:junit4] 2> 246632 T463 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 246650 T463 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 246661 T463 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 246662 T463 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 246662 T463 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:42723/bmn/collection1/
[junit4:junit4] 2> 246662 T463 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 246663 T463 oasc.SyncStrategy.syncToMe http://127.0.0.1:42723/bmn/collection1/ has no replicas
[junit4:junit4] 2> 246663 T463 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:42723/bmn/collection1/
[junit4:junit4] 2> 246663 T463 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 247676 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 247693 T460 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> 247741 T463 oasc.ZkController.register We are http://127.0.0.1:42723/bmn/collection1/ and leader is http://127.0.0.1:42723/bmn/collection1/
[junit4:junit4] 2> 247741 T463 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42723/bmn
[junit4:junit4] 2> 247741 T463 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 247741 T463 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 247741 T463 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 247743 T463 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 247744 T438 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 247745 T438 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 247745 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 247758 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 247759 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 247761 T467 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15b06b name:ZooKeeperConnection Watcher:127.0.0.1:42720/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 247761 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 247763 T438 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 247766 T438 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 247956 T438 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 247958 T438 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:42727
[junit4:junit4] 2> 247959 T438 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 247959 T438 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 247959 T438 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369098667750
[junit4:junit4] 2> 247960 T438 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369098667750/solr.xml
[junit4:junit4] 2> 247960 T438 oasc.CoreContainer.<init> New CoreContainer 837122981
[junit4:junit4] 2> 247961 T438 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369098667750/'
[junit4:junit4] 2> 247961 T438 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369098667750/'
[junit4:junit4] 2> 248052 T438 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 248052 T438 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 248053 T438 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 248053 T438 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 248054 T438 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 248054 T438 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 248054 T438 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 248055 T438 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 248055 T438 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 248055 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 248067 T438 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 248068 T438 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42720/solr
[junit4:junit4] 2> 248068 T438 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 248069 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 248073 T478 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c82eb65 name:ZooKeeperConnection Watcher:127.0.0.1:42720 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 248074 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 248118 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 248126 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 248128 T480 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e63924e name:ZooKeeperConnection Watcher:127.0.0.1:42720/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 248128 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 248169 T438 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 249172 T438 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42727_bmn
[junit4:junit4] 2> 249174 T438 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42727_bmn
[junit4:junit4] 2> 249178 T480 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 249178 T460 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 249178 T467 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 249178 T460 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> 249197 T481 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369098667750/collection1
[junit4:junit4] 2> 249197 T481 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 249198 T481 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 249198 T481 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 249200 T481 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369098667750/collection1/'
[junit4:junit4] 2> 249201 T481 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1369098667750/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 249202 T481 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1369098667750/collection1/lib/README' to classloader
[junit4:junit4] 2> 249207 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 249208 T461 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:42723_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42723/bmn"}
[junit4:junit4] 2> 249219 T480 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> 249220 T467 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> 249219 T460 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> 249241 T481 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 249287 T481 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 249389 T481 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 249394 T481 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 249860 T481 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 249864 T481 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 249867 T481 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 249872 T481 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 249907 T481 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 249907 T481 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369098667750/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty1/
[junit4:junit4] 2> 249908 T481 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@796d470b
[junit4:junit4] 2> 249908 T481 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 249909 T481 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty1
[junit4:junit4] 2> 249909 T481 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty1/index/
[junit4:junit4] 2> 249910 T481 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 249910 T481 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty1/index
[junit4:junit4] 2> 249914 T481 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@365568bf lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a5d23f1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 249915 T481 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 249919 T481 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 249919 T481 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 249920 T481 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 249921 T481 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 249922 T481 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 249922 T481 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 249923 T481 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 249923 T481 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 249924 T481 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 249940 T481 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 249948 T481 oass.SolrIndexSearcher.<init> Opening Searcher@6faca3f6 main
[junit4:junit4] 2> 249949 T481 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty1/tlog
[junit4:junit4] 2> 249950 T481 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 249950 T481 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 249956 T482 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6faca3f6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 249959 T481 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 249959 T481 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 250726 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 250727 T461 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:42727_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42727/bmn"}
[junit4:junit4] 2> 250727 T461 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 250728 T461 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 250733 T480 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> 250733 T467 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> 250733 T460 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> 250962 T481 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 250962 T481 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42727/bmn collection:collection1 shard:shard1
[junit4:junit4] 2> 250963 T481 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 250981 T481 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 250992 T481 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 250992 T481 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 250993 T481 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:42727/bmn/collection1/
[junit4:junit4] 2> 250993 T481 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 250993 T481 oasc.SyncStrategy.syncToMe http://127.0.0.1:42727/bmn/collection1/ has no replicas
[junit4:junit4] 2> 250994 T481 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:42727/bmn/collection1/
[junit4:junit4] 2> 250994 T481 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 252245 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 252263 T480 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> 252263 T467 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> 252263 T460 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> 252276 T481 oasc.ZkController.register We are http://127.0.0.1:42727/bmn/collection1/ and leader is http://127.0.0.1:42727/bmn/collection1/
[junit4:junit4] 2> 252276 T481 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42727/bmn
[junit4:junit4] 2> 252276 T481 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 252277 T481 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 252277 T481 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 252279 T481 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 252280 T438 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 252281 T438 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 252282 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 252584 T438 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 252588 T438 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:42730
[junit4:junit4] 2> 252588 T438 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 252589 T438 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 252590 T438 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369098672283
[junit4:junit4] 2> 252590 T438 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369098672283/solr.xml
[junit4:junit4] 2> 252591 T438 oasc.CoreContainer.<init> New CoreContainer 984673220
[junit4:junit4] 2> 252591 T438 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369098672283/'
[junit4:junit4] 2> 252592 T438 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369098672283/'
[junit4:junit4] 2> 252734 T438 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 252735 T438 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 252735 T438 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 252736 T438 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 252737 T438 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 252737 T438 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 252738 T438 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 252738 T438 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 252739 T438 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 252739 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 252758 T438 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 252759 T438 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42720/solr
[junit4:junit4] 2> 252760 T438 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 252761 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 252764 T494 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2273c2ef name:ZooKeeperConnection Watcher:127.0.0.1:42720 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 252765 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 252777 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 252791 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 252793 T496 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11b6864a name:ZooKeeperConnection Watcher:127.0.0.1:42720/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 252793 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 252800 T438 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 253778 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 253779 T461 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:42727_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42727/bmn"}
[junit4:junit4] 2> 253800 T480 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> 253800 T496 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> 253800 T467 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> 253800 T460 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> 253804 T438 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42730_bmn
[junit4:junit4] 2> 253806 T438 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42730_bmn
[junit4:junit4] 2> 253814 T467 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> 253814 T480 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 253814 T496 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 253814 T480 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> 253814 T460 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 253815 T496 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> 253815 T460 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> 253816 T467 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 253822 T497 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369098672283/collection1
[junit4:junit4] 2> 253823 T497 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 253824 T497 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 253824 T497 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 253825 T497 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369098672283/collection1/'
[junit4:junit4] 2> 253827 T497 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1369098672283/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 253828 T497 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1369098672283/collection1/lib/README' to classloader
[junit4:junit4] 2> 253885 T497 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 253951 T497 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 254053 T497 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 254060 T497 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 254579 T497 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 254583 T497 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 254586 T497 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 254591 T497 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 254621 T497 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 254622 T497 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369098672283/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty2/
[junit4:junit4] 2> 254622 T497 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@796d470b
[junit4:junit4] 2> 254623 T497 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 254624 T497 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty2
[junit4:junit4] 2> 254624 T497 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty2/index/
[junit4:junit4] 2> 254625 T497 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 254625 T497 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty2/index
[junit4:junit4] 2> 254629 T497 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@484eb284 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7da4c9ee),segFN=segments_1,generation=1}
[junit4:junit4] 2> 254629 T497 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 254633 T497 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 254633 T497 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 254634 T497 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 254635 T497 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 254636 T497 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 254636 T497 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 254636 T497 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 254637 T497 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 254638 T497 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 254656 T497 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 254665 T497 oass.SolrIndexSearcher.<init> Opening Searcher@54c78332 main
[junit4:junit4] 2> 254665 T497 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty2/tlog
[junit4:junit4] 2> 254666 T497 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 254667 T497 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 254672 T498 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@54c78332 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 254674 T497 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 254675 T497 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 255307 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 255308 T461 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:42730_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42730/bmn"}
[junit4:junit4] 2> 255308 T461 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 255309 T461 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 255314 T460 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> 255314 T467 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> 255314 T480 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> 255314 T496 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> 255678 T497 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 255678 T497 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42730/bmn collection:collection1 shard:shard2
[junit4:junit4] 2> 255679 T497 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 255696 T497 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 255708 T497 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 255708 T497 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 255709 T497 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:42730/bmn/collection1/
[junit4:junit4] 2> 255709 T497 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 255709 T497 oasc.SyncStrategy.syncToMe http://127.0.0.1:42730/bmn/collection1/ has no replicas
[junit4:junit4] 2> 255710 T497 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:42730/bmn/collection1/
[junit4:junit4] 2> 255710 T497 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 256827 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 256844 T480 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> 256844 T496 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> 256844 T467 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> 256844 T460 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> 256890 T497 oasc.ZkController.register We are http://127.0.0.1:42730/bmn/collection1/ and leader is http://127.0.0.1:42730/bmn/collection1/
[junit4:junit4] 2> 256890 T497 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42730/bmn
[junit4:junit4] 2> 256890 T497 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 256891 T497 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 256891 T497 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 256894 T497 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 256895 T438 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 256896 T438 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 256896 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 257100 T438 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 257103 T438 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:42733
[junit4:junit4] 2> 257103 T438 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 257104 T438 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 257104 T438 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369098676892
[junit4:junit4] 2> 257105 T438 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369098676892/solr.xml
[junit4:junit4] 2> 257105 T438 oasc.CoreContainer.<init> New CoreContainer 1671670890
[junit4:junit4] 2> 257105 T438 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369098676892/'
[junit4:junit4] 2> 257106 T438 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369098676892/'
[junit4:junit4] 2> 257202 T438 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 257202 T438 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 257203 T438 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 257203 T438 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 257203 T438 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 257204 T438 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 257204 T438 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 257205 T438 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 257205 T438 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 257205 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 257218 T438 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 257219 T438 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42720/solr
[junit4:junit4] 2> 257219 T438 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 257220 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 257223 T510 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d753145 name:ZooKeeperConnection Watcher:127.0.0.1:42720 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 257224 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 257236 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 257246 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 257248 T512 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@60cd0e77 name:ZooKeeperConnection Watcher:127.0.0.1:42720/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 257248 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 257260 T438 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 258264 T438 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42733_bmn
[junit4:junit4] 2> 258291 T438 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42733_bmn
[junit4:junit4] 2> 258320 T467 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> 258320 T512 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 258320 T480 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 258320 T460 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 258320 T496 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 258321 T460 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> 258321 T480 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> 258321 T496 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> 258323 T467 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 258328 T513 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369098676892/collection1
[junit4:junit4] 2> 258328 T513 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 258329 T513 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 258329 T513 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 258331 T513 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369098676892/collection1/'
[junit4:junit4] 2> 258332 T513 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1369098676892/collection1/lib/README' to classloader
[junit4:junit4] 2> 258333 T513 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1369098676892/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 258358 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 258359 T461 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:42730_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42730/bmn"}
[junit4:junit4] 2> 258372 T480 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> 258372 T467 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> 258372 T512 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> 258372 T460 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> 258372 T496 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> 258377 T513 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 258430 T513 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 258531 T513 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 258538 T513 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 259120 T513 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 259124 T513 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 259127 T513 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 259132 T513 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 259165 T513 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 259165 T513 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369098676892/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty3/
[junit4:junit4] 2> 259165 T513 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@796d470b
[junit4:junit4] 2> 259166 T513 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 259167 T513 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty3
[junit4:junit4] 2> 259167 T513 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty3/index/
[junit4:junit4] 2> 259167 T513 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 259168 T513 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty3/index
[junit4:junit4] 2> 259173 T513 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39a69e6b lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ab8dd93),segFN=segments_1,generation=1}
[junit4:junit4] 2> 259173 T513 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 259176 T513 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 259177 T513 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 259178 T513 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 259179 T513 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 259179 T513 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 259180 T513 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 259180 T513 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 259181 T513 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 259181 T513 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 259199 T513 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 259207 T513 oass.SolrIndexSearcher.<init> Opening Searcher@290cfde1 main
[junit4:junit4] 2> 259208 T513 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty3/tlog
[junit4:junit4] 2> 259209 T513 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 259209 T513 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 259215 T514 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@290cfde1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 259218 T513 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 259218 T513 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 259878 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 259879 T461 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:42733_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42733/bmn"}
[junit4:junit4] 2> 259879 T461 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 259879 T461 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 259924 T480 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> 259924 T460 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> 259924 T496 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> 259924 T467 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> 259928 T512 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> 260223 T513 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 260223 T513 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42733/bmn collection:collection1 shard:shard1
[junit4:junit4] 2> 260227 T513 oasc.ZkController.register We are http://127.0.0.1:42733/bmn/collection1/ and leader is http://127.0.0.1:42727/bmn/collection1/
[junit4:junit4] 2> 260228 T513 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42733/bmn
[junit4:junit4] 2> 260228 T513 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 260228 T513 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C18 name=collection1 org.apache.solr.core.SolrCore@3f5108b2 url=http://127.0.0.1:42733/bmn/collection1 node=127.0.0.1:42733_bmn C18_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:42733_bmn, base_url=http://127.0.0.1:42733/bmn}
[junit4:junit4] 2> 260229 T515 C18 P42733 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 260230 T515 C18 P42733 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 260230 T513 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 260230 T515 C18 P42733 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 260230 T515 C18 P42733 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 260231 T438 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 260232 T438 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 260232 T515 C18 P42733 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 260232 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 260258 T470 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 260512 T438 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 260515 T438 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:42737
[junit4:junit4] 2> 260516 T438 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 260516 T438 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 260517 T438 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369098680239
[junit4:junit4] 2> 260517 T438 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369098680239/solr.xml
[junit4:junit4] 2> 260518 T438 oasc.CoreContainer.<init> New CoreContainer 2032180116
[junit4:junit4] 2> 260518 T438 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369098680239/'
[junit4:junit4] 2> 260519 T438 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369098680239/'
[junit4:junit4] 2> 260651 T438 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 260652 T438 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 260652 T438 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 260652 T438 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 260653 T438 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 260653 T438 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 260654 T438 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 260654 T438 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 260655 T438 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 260656 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 260673 T438 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 260674 T438 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42720/solr
[junit4:junit4] 2> 260674 T438 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 260675 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 260679 T527 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@64aff033 name:ZooKeeperConnection Watcher:127.0.0.1:42720 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 260680 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 260682 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 260695 T438 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 260697 T529 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4ea653f2 name:ZooKeeperConnection Watcher:127.0.0.1:42720/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 260697 T438 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 260703 T438 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 261435 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 261436 T461 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:42733_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42733/bmn"}
[junit4:junit4] 2> 261483 T480 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> 261484 T467 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> 261484 T460 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> 261483 T496 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> 261483 T529 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> 261483 T512 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> 261707 T438 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42737_bmn
[junit4:junit4] 2> 261710 T438 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42737_bmn
[junit4:junit4] 2> 261713 T467 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> 261713 T496 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 261713 T460 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 261713 T512 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 261713 T480 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 261714 T512 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> 261714 T460 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> 261715 T467 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 261714 T529 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 261714 T496 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> 261716 T529 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> 261714 T480 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> 261728 T530 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369098680239/collection1
[junit4:junit4] 2> 261728 T530 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 261729 T530 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 261729 T530 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 261731 T530 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369098680239/collection1/'
[junit4:junit4] 2> 261733 T530 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1369098680239/collection1/lib/README' to classloader
[junit4:junit4] 2> 261733 T530 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1369098680239/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 261790 T530 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 261857 T530 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 261958 T530 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 261966 T530 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 262261 T470 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 262261 T470 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:42733_bmn&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 262583 T530 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 262587 T530 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 262590 T530 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 262596 T530 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 262629 T530 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 262630 T530 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369098680239/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty4/
[junit4:junit4] 2> 262630 T530 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@796d470b
[junit4:junit4] 2> 262631 T530 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 262631 T530 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty4
[junit4:junit4] 2> 262632 T530 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty4/index/
[junit4:junit4] 2> 262632 T530 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 262634 T530 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty4/index
[junit4:junit4] 2> 262638 T530 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@46ea92dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@4913aa9c),segFN=segments_1,generation=1}
[junit4:junit4] 2> 262638 T530 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 262642 T530 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 262642 T530 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 262643 T530 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 262644 T530 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 262645 T530 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 262645 T530 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 262645 T530 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 262646 T530 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 262647 T530 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 262663 T530 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 262671 T530 oass.SolrIndexSearcher.<init> Opening Searcher@4abff439 main
[junit4:junit4] 2> 262671 T530 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty4/tlog
[junit4:junit4] 2> 262673 T530 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 262673 T530 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 262678 T531 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4abff439 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 262681 T530 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 262681 T530 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 262990 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 262991 T461 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:42737_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42737/bmn"}
[junit4:junit4] 2> 262991 T461 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 262991 T461 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 263046 T496 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> 263046 T512 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> 263046 T467 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> 263046 T460 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> 263046 T529 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> 263046 T480 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> 263684 T530 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 263684 T530 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42737/bmn collection:collection1 shard:shard2
[junit4:junit4] 2> 263714 T530 oasc.ZkController.register We are http://127.0.0.1:42737/bmn/collection1/ and leader is http://127.0.0.1:42730/bmn/collection1/
[junit4:junit4] 2> 263715 T530 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42737/bmn
[junit4:junit4] 2> 263715 T530 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 263715 T530 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C19 name=collection1 org.apache.solr.core.SolrCore@615d0056 url=http://127.0.0.1:42737/bmn/collection1 node=127.0.0.1:42737_bmn C19_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:42737_bmn, base_url=http://127.0.0.1:42737/bmn}
[junit4:junit4] 2> 263716 T532 C19 P42737 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 263716 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 263717 T532 C19 P42737 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 263717 T532 C19 P42737 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 263718 T532 C19 P42737 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 263718 T438 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 263719 T438 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 263719 T532 C19 P42737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 263719 T438 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 263739 T438 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 263740 T486 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 263740 T438 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 263741 T438 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 263742 T438 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C18_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:42733_bmn, base_url=http://127.0.0.1:42733/bmn}
[junit4:junit4] 2> 264263 T515 C18 P42733 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:42727/bmn/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 264263 T515 C18 P42733 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:42733/bmn START replicas=[http://127.0.0.1:42727/bmn/collection1/] nUpdates=100
[junit4:junit4] 2> 264264 T515 C18 P42733 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 264265 T515 C18 P42733 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 264265 T515 C18 P42733 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 264266 T515 C18 P42733 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 264266 T515 C18 P42733 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 264266 T515 C18 P42733 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:42727/bmn/collection1/. core=collection1
[junit4:junit4] 2> 264267 T515 C18 P42733 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C20 name=collection1 org.apache.solr.core.SolrCore@2ca907da url=http://127.0.0.1:42727/bmn/collection1 node=127.0.0.1:42727_bmn C20_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42727_bmn, base_url=http://127.0.0.1:42727/bmn, leader=true}
[junit4:junit4] 2> 264274 T471 C20 P42727 oasc.SolrCore.execute [collection1] webapp=/bmn path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 264280 T472 C20 P42727 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 264284 T472 C20 P42727 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@365568bf lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a5d23f1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 264284 T472 C20 P42727 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 264285 T472 C20 P42727 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@365568bf lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a5d23f1),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@365568bf lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a5d23f1),segFN=segments_2,generation=2}
[junit4:junit4] 2> 264286 T472 C20 P42727 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 264286 T472 C20 P42727 oass.SolrIndexSearcher.<init> Opening Searcher@7a6713b6 realtime
[junit4:junit4] 2> 264287 T472 C20 P42727 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 264287 T472 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn 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> 264288 T515 C18 P42733 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 264289 T515 C18 P42733 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 264292 T473 C20 P42727 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 264292 T473 C20 P42727 oasc.SolrCore.execute [collection1] webapp=/bmn path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 264293 T515 C18 P42733 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 264293 T515 C18 P42733 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 264294 T515 C18 P42733 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 264297 T473 C20 P42727 oasc.SolrCore.execute [collection1] webapp=/bmn path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 264298 T515 C18 P42733 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 264299 T515 C18 P42733 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty3/index.20130521031124282
[junit4:junit4] 2> 264299 T515 C18 P42733 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@228060c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4942725) fullCopy=false
[junit4:junit4] 2> 264303 T473 C20 P42727 oasc.SolrCore.execute [collection1] webapp=/bmn path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 264304 T515 C18 P42733 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 264305 T515 C18 P42733 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 264306 T515 C18 P42733 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 264308 T515 C18 P42733 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39a69e6b lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ab8dd93),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39a69e6b lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ab8dd93),segFN=segments_2,generation=2}
[junit4:junit4] 2> 264309 T515 C18 P42733 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 264309 T515 C18 P42733 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 264309 T515 C18 P42733 oass.SolrIndexSearcher.<init> Opening Searcher@2253ad2a main
[junit4:junit4] 2> 264311 T514 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2253ad2a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 264312 T515 C18 P42733 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty3/index.20130521031124282 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty3/index.20130521031124282;done=true>>]
[junit4:junit4] 2> 264312 T515 C18 P42733 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty3/index.20130521031124282
[junit4:junit4] 2> 264312 T515 C18 P42733 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty3/index.20130521031124282
[junit4:junit4] 2> 264313 T515 C18 P42733 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 264313 T515 C18 P42733 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 264313 T515 C18 P42733 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 264313 T515 C18 P42733 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 264341 T515 C18 P42733 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 264582 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 264583 T461 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:42737_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42737/bmn"}
[junit4:junit4] 2> 264587 T461 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:42733_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42733/bmn"}
[junit4:junit4] 2> 264600 T480 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> 264600 T467 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> 264601 T529 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> 264600 T460 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> 264600 T496 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> 264600 T512 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> 264741 T486 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 264741 T486 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:42737_bmn&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 264744 T438 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 265747 T438 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C19_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:42737_bmn, base_url=http://127.0.0.1:42737/bmn}
[junit4:junit4] 2> 266743 T532 C19 P42737 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:42730/bmn/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 266743 T532 C19 P42737 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:42737/bmn START replicas=[http://127.0.0.1:42730/bmn/collection1/] nUpdates=100
[junit4:junit4] 2> 266744 T532 C19 P42737 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 266745 T532 C19 P42737 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 266745 T532 C19 P42737 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 266745 T532 C19 P42737 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 266745 T532 C19 P42737 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 266746 T532 C19 P42737 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:42730/bmn/collection1/. core=collection1
[junit4:junit4] 2> 266746 T532 C19 P42737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 266750 T438 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C21 name=collection1 org.apache.solr.core.SolrCore@18738189 url=http://127.0.0.1:42730/bmn/collection1 node=127.0.0.1:42730_bmn C21_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42730_bmn, base_url=http://127.0.0.1:42730/bmn, leader=true}
[junit4:junit4] 2> 266753 T487 C21 P42730 oasc.SolrCore.execute [collection1] webapp=/bmn path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 266760 T488 C21 P42730 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 266763 T488 C21 P42730 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@484eb284 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7da4c9ee),segFN=segments_1,generation=1}
[junit4:junit4] 2> 266763 T488 C21 P42730 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 266764 T488 C21 P42730 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@484eb284 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7da4c9ee),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@484eb284 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7da4c9ee),segFN=segments_2,generation=2}
[junit4:junit4] 2> 266765 T488 C21 P42730 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 266765 T488 C21 P42730 oass.SolrIndexSearcher.<init> Opening Searcher@4bf5f0bd realtime
[junit4:junit4] 2> 266766 T488 C21 P42730 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 266766 T488 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 266768 T532 C19 P42737 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 266768 T532 C19 P42737 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 266771 T489 C21 P42730 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 266771 T489 C21 P42730 oasc.SolrCore.execute [collection1] webapp=/bmn path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 266772 T532 C19 P42737 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 266772 T532 C19 P42737 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 266773 T532 C19 P42737 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 266776 T489 C21 P42730 oasc.SolrCore.execute [collection1] webapp=/bmn path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 266777 T532 C19 P42737 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 266778 T532 C19 P42737 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty4/index.20130521031126761
[junit4:junit4] 2> 266778 T532 C19 P42737 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d914329 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5a15c4f1) fullCopy=false
[junit4:junit4] 2> 266781 T489 C21 P42730 oasc.SolrCore.execute [collection1] webapp=/bmn path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 266783 T532 C19 P42737 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 266784 T532 C19 P42737 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 266784 T532 C19 P42737 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 266786 T532 C19 P42737 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@46ea92dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@4913aa9c),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@46ea92dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@4913aa9c),segFN=segments_2,generation=2}
[junit4:junit4] 2> 266787 T532 C19 P42737 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 266787 T532 C19 P42737 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 266787 T532 C19 P42737 oass.SolrIndexSearcher.<init> Opening Searcher@15883401 main
[junit4:junit4] 2> 266789 T531 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15883401 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 266789 T532 C19 P42737 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty4/index.20130521031126761 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty4/index.20130521031126761;done=true>>]
[junit4:junit4] 2> 266790 T532 C19 P42737 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty4/index.20130521031126761
[junit4:junit4] 2> 266790 T532 C19 P42737 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1369098663751/jetty4/index.20130521031126761
[junit4:junit4] 2> 266790 T532 C19 P42737 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 266791 T532 C19 P42737 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 266791 T532 C19 P42737 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 266791 T532 C19 P42737 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 266793 T532 C19 P42737 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 267616 T461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 267618 T461 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:42737_bmn",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42737/bmn"}
[junit4:junit4] 2> 267635 T496 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> 267635 T467 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> 267635 T480 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> 267635 T529 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> 267635 T512 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> 267635 T460 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> 267753 T438 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 267755 T438 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C22 name=collection1 org.apache.solr.core.SolrCore@7fb19bc5 url=http://127.0.0.1:42723/bmn/collection1 node=127.0.0.1:42723_bmn C22_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:42723_bmn, base_url=http://127.0.0.1:42723/bmn, leader=true}
[junit4:junit4] 2> 267764 T450 C22 P42723 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 267767 T450 C22 P42723 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4ffb2490 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67d1de8b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 267768 T450 C22 P42723 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 267769 T450 C22 P42723 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4ffb2490 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67d1de8b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4ffb2490 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67d1de8b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 267769 T450 C22 P42723 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 267770 T450 C22 P42723 oass.SolrIndexSearcher.<init> Opening Searcher@7be5556a main
[junit4:junit4] 2> 267770 T450 C22 P42723 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 267771 T464 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7be5556a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 267772 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 267787 T490 C21 P42730 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 267789 T490 C21 P42730 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@484eb284 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7da4c9ee),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@484eb284 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7da4c9ee),segFN=segments_3,generation=3}
[junit4:junit4] 2> 267789 T490 C21 P42730 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 267790 T490 C21 P42730 oass.SolrIndexSearcher.<init> Opening Searcher@b8150c1 main
[junit4:junit4] 2> 267790 T490 C21 P42730 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 267791 T498 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b8150c1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 267792 T490 C21 P42730 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:42727/bmn/collection1/, StdNode: http://127.0.0.1:42733/bmn/collection1/, StdNode: http://127.0.0.1:42737/bmn/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 267796 T474 C20 P42727 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 267798 T474 C20 P42727 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@365568bf lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a5d23f1),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@365568bf lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a5d23f1),segFN=segments_3,generation=3}
[junit4:junit4] 2> 267798 T474 C20 P42727 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 267799 T474 C20 P42727 oass.SolrIndexSearcher.<init> Opening Searcher@3a2ef3ba main
[junit4:junit4] 2> 267799 T474 C20 P42727 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 267800 T482 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3a2ef3ba main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 267801 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> C19_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42737_bmn, base_url=http://127.0.0.1:42737/bmn}
[junit4:junit4] 2> 267804 T519 C19 P42737 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C18_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42733_bmn, base_url=http://127.0.0.1:42733/bmn}
[junit4:junit4] 2> 267804 T502 C18 P42733 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 267806 T519 C19 P42737 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@46ea92dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@4913aa9c),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@46ea92dd lockFactory=org.apache.lucene.store.NativeFSLockFactory@4913aa9c),segFN=segments_3,generation=3}
[junit4:junit4] 2> 267806 T502 C18 P42733 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39a69e6b lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ab8dd93),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39a69e6b lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ab8dd93),segFN=segments_3,generation=3}
[junit4:junit4] 2> 267806 T519 C19 P42737 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 267807 T502 C18 P42733 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 267808 T519 C19 P42737 oass.SolrIndexSearcher.<init> Opening Searcher@20fcc207 main
[junit4:junit4] 2> 267808 T502 C18 P42733 oass.SolrIndexSearcher.<init> Opening Searcher@16a4599e main
[junit4:junit4] 2> 267809 T519 C19 P42737 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 267809 T502 C18 P42733 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 267810 T514 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16a4599e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 267809 T531 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@20fcc207 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 267810 T502 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn 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> 267811 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn 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> 267812 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 25
[junit4:junit4] 2> 267813 T438 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 267817 T475 C20 P42727 oasc.SolrCore.execute [collection1] webapp=/bmn path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 267821 T503 C18 P42733 oasc.SolrCore.execute [collection1] webapp=/bmn path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 267823 T491 C21 P42730 oasc.SolrCore.execute [collection1] webapp=/bmn path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 267826 T520 C19 P42737 oasc.SolrCore.execute [collection1] webapp=/bmn path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 269873 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435604027785084928)} 0 34
[junit4:junit4] 2> 269882 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={update.distrib=FROMLEADER&_version_=-1435604027818639360&update.from=http://127.0.0.1:42727/bmn/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435604027818639360)} 0 2
[junit4:junit4] 2> 269886 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={update.distrib=FROMLEADER&_version_=-1435604027822833664&update.from=http://127.0.0.1:42730/bmn/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435604027822833664)} 0 1
[junit4:junit4] 2> 269887 T492 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435604027822833664)} 0 7
[junit4:junit4] 2> 269888 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435604027818639360)} 0 12
[junit4:junit4] 2> 269893 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[a!0 (1435604027836465152)]} 0 1
[junit4:junit4] 2> 269902 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1435604027841708032)]} 0 1
[junit4:junit4] 2> 269903 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[a!0 (1435604027841708032)]} 0 6
[junit4:junit4] 2> 269907 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[b!1 (1435604027850096640)]} 0 1
[junit4:junit4] 2> 269914 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1435604027854290944)]} 0 1
[junit4:junit4] 2> 269915 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[b!1 (1435604027854290944)]} 0 5
[junit4:junit4] 2> 269919 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[c!2 (1435604027862679552)]} 0 1
[junit4:junit4] 2> 269926 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1435604027867922432)]} 0 1
[junit4:junit4] 2> 269927 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[c!2 (1435604027867922432)]} 0 5
[junit4:junit4] 2> 269931 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[d!3 (1435604027876311040)]} 0 1
[junit4:junit4] 2> 269943 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1435604027884699648)]} 0 1
[junit4:junit4] 2> 269944 T492 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1435604027884699648)]} 0 6
[junit4:junit4] 2> 269945 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[d!3]} 0 10
[junit4:junit4] 2> 269949 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[e!4 (1435604027895185408)]} 0 1
[junit4:junit4] 2> 269957 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1435604027900428288)]} 0 1
[junit4:junit4] 2> 269958 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[e!4 (1435604027900428288)]} 0 5
[junit4:junit4] 2> 269962 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[f!5 (1435604027908816896)]} 0 1
[junit4:junit4] 2> 269970 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1435604027913011200)]} 0 1
[junit4:junit4] 2> 269971 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[f!5 (1435604027913011200)]} 0 6
[junit4:junit4] 2> 269975 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[g!6 (1435604027922448384)]} 0 1
[junit4:junit4] 2> 269983 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1435604027927691264)]} 0 1
[junit4:junit4] 2> 269984 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[g!6 (1435604027927691264)]} 0 5
[junit4:junit4] 2> 269988 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[h!7 (1435604027936079872)]} 0 1
[junit4:junit4] 2> 269997 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1435604027941322752)]} 0 1
[junit4:junit4] 2> 269998 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[h!7 (1435604027941322752)]} 0 6
[junit4:junit4] 2> 270002 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[i!8 (1435604027950759936)]} 0 1
[junit4:junit4] 2> 270018 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1435604027962294272)]} 0 1
[junit4:junit4] 2> 270019 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!8 (1435604027962294272)]} 0 6
[junit4:junit4] 2> 270020 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[i!8]} 0 11
[junit4:junit4] 2> 270024 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[j!9 (1435604027973828608)]} 0 1
[junit4:junit4] 2> 270033 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1435604027979071488)]} 0 0
[junit4:junit4] 2> 270035 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[j!9 (1435604027979071488)]} 0 7
[junit4:junit4] 2> 270039 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[k!10 (1435604027989557248)]} 0 1
[junit4:junit4] 2> 270046 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1435604027993751552)]} 0 1
[junit4:junit4] 2> 270047 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[k!10 (1435604027993751552)]} 0 5
[junit4:junit4] 2> 270051 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[l!11 (1435604028002140160)]} 0 1
[junit4:junit4] 2> 270060 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1435604028007383040)]} 0 0
[junit4:junit4] 2> 270061 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[l!11 (1435604028007383040)]} 0 5
[junit4:junit4] 2> 270065 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[m!12 (1435604028016820224)]} 0 1
[junit4:junit4] 2> 270073 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1435604028021014528)]} 0 1
[junit4:junit4] 2> 270074 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[m!12 (1435604028021014528)]} 0 6
[junit4:junit4] 2> 270078 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[n!13 (1435604028030451712)]} 0 1
[junit4:junit4] 2> 270085 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1435604028034646016)]} 0 1
[junit4:junit4] 2> 270086 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[n!13 (1435604028034646016)]} 0 5
[junit4:junit4] 2> 270090 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[o!14 (1435604028043034624)]} 0 1
[junit4:junit4] 2> 270098 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1435604028047228928)]} 0 1
[junit4:junit4] 2> 270099 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[o!14 (1435604028047228928)]} 0 6
[junit4:junit4] 2> 270103 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[p!15 (1435604028056666112)]} 0 1
[junit4:junit4] 2> 270110 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1435604028060860416)]} 0 1
[junit4:junit4] 2> 270111 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[p!15 (1435604028060860416)]} 0 5
[junit4:junit4] 2> 270115 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[q!16 (1435604028069249024)]} 0 1
[junit4:junit4] 2> 270127 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1435604028077637632)]} 0 1
[junit4:junit4] 2> 270128 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1435604028077637632)]} 0 6
[junit4:junit4] 2> 270129 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[q!16]} 0 10
[junit4:junit4] 2> 270133 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[r!17 (1435604028088123392)]} 0 1
[junit4:junit4] 2> 270141 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1435604028092317696)]} 0 0
[junit4:junit4] 2> 270142 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[r!17 (1435604028092317696)]} 0 6
[junit4:junit4] 2> 270146 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[s!18 (1435604028101754880)]} 0 1
[junit4:junit4] 2> 270158 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1435604028109094912)]} 0 1
[junit4:junit4] 2> 270159 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!18 (1435604028109094912)]} 0 7
[junit4:junit4] 2> 270160 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[s!18]} 0 11
[junit4:junit4] 2> 270164 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[t!19 (1435604028120629248)]} 0 1
[junit4:junit4] 2> 270171 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1435604028124823552)]} 0 0
[junit4:junit4] 2> 270173 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[t!19 (1435604028124823552)]} 0 6
[junit4:junit4] 2> 270177 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[u!20 (1435604028134260736)]} 0 1
[junit4:junit4] 2> 270184 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1435604028138455040)]} 0 0
[junit4:junit4] 2> 270185 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[u!20 (1435604028138455040)]} 0 5
[junit4:junit4] 2> 270190 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[v!21 (1435604028147892224)]} 0 1
[junit4:junit4] 2> 270200 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1435604028155232256)]} 0 1
[junit4:junit4] 2> 270201 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!21 (1435604028155232256)]} 0 5
[junit4:junit4] 2> 270202 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[v!21]} 0 9
[junit4:junit4] 2> 270206 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[w!22 (1435604028164669440)]} 0 1
[junit4:junit4] 2> 270216 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1435604028172009472)]} 0 1
[junit4:junit4] 2> 270217 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!22 (1435604028172009472)]} 0 5
[junit4:junit4] 2> 270218 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[w!22]} 0 9
[junit4:junit4] 2> 270222 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[x!23 (1435604028181446656)]} 0 1
[junit4:junit4] 2> 270233 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1435604028188786688)]} 0 1
[junit4:junit4] 2> 270234 T492 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1435604028188786688)]} 0 5
[junit4:junit4] 2> 270235 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[x!23]} 0 10
[junit4:junit4] 2> 270239 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[y!24 (1435604028199272448)]} 0 1
[junit4:junit4] 2> 270246 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1435604028203466752)]} 0 0
[junit4:junit4] 2> 270247 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[y!24 (1435604028203466752)]} 0 5
[junit4:junit4] 2> 270251 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[z!25 (1435604028211855360)]} 0 1
[junit4:junit4] 2> 270258 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1435604028216049664)]} 0 0
[junit4:junit4] 2> 270259 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[z!25 (1435604028216049664)]} 0 5
[junit4:junit4] 2> 270263 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[a!26 (1435604028224438272)]} 0 1
[junit4:junit4] 2> 270270 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1435604028228632576)]} 0 1
[junit4:junit4] 2> 270271 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[a!26 (1435604028228632576)]} 0 5
[junit4:junit4] 2> 270275 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[b!27 (1435604028237021184)]} 0 1
[junit4:junit4] 2> 270283 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1435604028241215488)]} 0 1
[junit4:junit4] 2> 270284 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[b!27 (1435604028241215488)]} 0 6
[junit4:junit4] 2> 270288 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[c!28 (1435604028250652672)]} 0 1
[junit4:junit4] 2> 270295 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1435604028254846976)]} 0 1
[junit4:junit4] 2> 270296 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[c!28 (1435604028254846976)]} 0 5
[junit4:junit4] 2> 270300 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[d!29 (1435604028263235584)]} 0 1
[junit4:junit4] 2> 270311 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1435604028270575616)]} 0 1
[junit4:junit4] 2> 270312 T492 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1435604028270575616)]} 0 6
[junit4:junit4] 2> 270313 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[d!29]} 0 10
[junit4:junit4] 2> 270317 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[e!30 (1435604028281061376)]} 0 1
[junit4:junit4] 2> 270328 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1435604028288401408)]} 0 1
[junit4:junit4] 2> 270329 T492 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1435604028288401408)]} 0 6
[junit4:junit4] 2> 270330 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[e!30]} 0 10
[junit4:junit4] 2> 270334 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[f!31 (1435604028298887168)]} 0 1
[junit4:junit4] 2> 270341 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1435604028303081472)]} 0 1
[junit4:junit4] 2> 270342 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[f!31 (1435604028303081472)]} 0 5
[junit4:junit4] 2> 270346 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[g!32 (1435604028311470080)]} 0 1
[junit4:junit4] 2> 270357 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1435604028318810112)]} 0 1
[junit4:junit4] 2> 270358 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!32 (1435604028318810112)]} 0 6
[junit4:junit4] 2> 270359 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[g!32]} 0 10
[junit4:junit4] 2> 270363 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[h!33 (1435604028329295872)]} 0 0
[junit4:junit4] 2> 270375 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1435604028337684480)]} 0 0
[junit4:junit4] 2> 270377 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!33 (1435604028337684480)]} 0 6
[junit4:junit4] 2> 270378 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[h!33]} 0 11
[junit4:junit4] 2> 270382 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[i!34 (1435604028349218816)]} 0 1
[junit4:junit4] 2> 270393 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1435604028356558848)]} 0 1
[junit4:junit4] 2> 270394 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1435604028356558848)]} 0 6
[junit4:junit4] 2> 270395 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[i!34]} 0 10
[junit4:junit4] 2> 270399 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[j!35 (1435604028367044608)]} 0 1
[junit4:junit4] 2> 270411 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1435604028375433216)]} 0 1
[junit4:junit4] 2> 270412 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!35 (1435604028375433216)]} 0 5
[junit4:junit4] 2> 270413 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[j!35]} 0 10
[junit4:junit4] 2> 270417 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[k!36 (1435604028385918976)]} 0 1
[junit4:junit4] 2> 270425 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1435604028390113280)]} 0 1
[junit4:junit4] 2> 270426 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[k!36 (1435604028390113280)]} 0 6
[junit4:junit4] 2> 270430 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[l!37 (1435604028399550464)]} 0 1
[junit4:junit4] 2> 270441 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1435604028406890496)]} 0 1
[junit4:junit4] 2> 270442 T492 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1435604028406890496)]} 0 5
[junit4:junit4] 2> 270443 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[l!37]} 0 10
[junit4:junit4] 2> 270447 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[m!38 (1435604028417376256)]} 0 1
[junit4:junit4] 2> 270454 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1435604028421570560)]} 0 1
[junit4:junit4] 2> 270455 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[m!38 (1435604028421570560)]} 0 5
[junit4:junit4] 2> 270459 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[n!39 (1435604028429959168)]} 0 1
[junit4:junit4] 2> 270470 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1435604028437299200)]} 0 1
[junit4:junit4] 2> 270471 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!39 (1435604028437299200)]} 0 6
[junit4:junit4] 2> 270472 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[n!39]} 0 9
[junit4:junit4] 2> 270476 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[o!40 (1435604028447784960)]} 0 1
[junit4:junit4] 2> 270483 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1435604028451979264)]} 0 1
[junit4:junit4] 2> 270484 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[o!40 (1435604028451979264)]} 0 5
[junit4:junit4] 2> 270489 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[p!41 (1435604028460367872)]} 0 1
[junit4:junit4] 2> 270497 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1435604028465610752)]} 0 1
[junit4:junit4] 2> 270498 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[p!41 (1435604028465610752)]} 0 6
[junit4:junit4] 2> 270502 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[q!42 (1435604028475047936)]} 0 1
[junit4:junit4] 2> 270513 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1435604028482387968)]} 0 0
[junit4:junit4] 2> 270514 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1435604028482387968)]} 0 6
[junit4:junit4] 2> 270515 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[q!42]} 0 10
[junit4:junit4] 2> 270519 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[r!43 (1435604028492873728)]} 0 1
[junit4:junit4] 2> 270527 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1435604028497068032)]} 0 1
[junit4:junit4] 2> 270528 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[r!43 (1435604028497068032)]} 0 6
[junit4:junit4] 2> 270532 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[s!44 (1435604028506505216)]} 0 1
[junit4:junit4] 2> 270540 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1435604028510699520)]} 0 1
[junit4:junit4] 2> 270541 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[s!44 (1435604028510699520)]} 0 6
[junit4:junit4] 2> 270545 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[t!45 (1435604028520136704)]} 0 1
[junit4:junit4] 2> 270553 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1435604028524331008)]} 0 1
[junit4:junit4] 2> 270554 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[t!45 (1435604028524331008)]} 0 6
[junit4:junit4] 2> 270558 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[u!46 (1435604028533768192)]} 0 1
[junit4:junit4] 2> 270569 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1435604028541108224)]} 0 1
[junit4:junit4] 2> 270570 T492 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!46 (1435604028541108224)]} 0 5
[junit4:junit4] 2> 270571 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[u!46]} 0 10
[junit4:junit4] 2> 270575 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[v!47 (1435604028551593984)]} 0 1
[junit4:junit4] 2> 270586 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1435604028558934016)]} 0 1
[junit4:junit4] 2> 270587 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1435604028558934016)]} 0 6
[junit4:junit4] 2> 270588 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[v!47]} 0 10
[junit4:junit4] 2> 270593 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[w!48 (1435604028569419776)]} 0 2
[junit4:junit4] 2> 270602 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1435604028574662656)]} 0 1
[junit4:junit4] 2> 270603 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[w!48 (1435604028574662656)]} 0 7
[junit4:junit4] 2> 270608 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[x!49 (1435604028585148416)]} 0 1
[junit4:junit4] 2> 270615 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1435604028590391296)]} 0 1
[junit4:junit4] 2> 270616 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[x!49 (1435604028590391296)]} 0 5
[junit4:junit4] 2> 270620 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[y!50 (1435604028598779904)]} 0 1
[junit4:junit4] 2> 270628 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1435604028604022784)]} 0 1
[junit4:junit4] 2> 270629 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[y!50 (1435604028604022784)]} 0 5
[junit4:junit4] 2> 270633 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[z!51 (1435604028612411392)]} 0 1
[junit4:junit4] 2> 270643 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1435604028619751424)]} 0 1
[junit4:junit4] 2> 270644 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!51 (1435604028619751424)]} 0 5
[junit4:junit4] 2> 270645 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[z!51]} 0 9
[junit4:junit4] 2> 270649 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[a!52 (1435604028629188608)]} 0 1
[junit4:junit4] 2> 270656 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1435604028632334336)]} 0 1
[junit4:junit4] 2> 270657 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[a!52 (1435604028632334336)]} 0 5
[junit4:junit4] 2> 270661 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[b!53 (1435604028641771520)]} 0 1
[junit4:junit4] 2> 270668 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1435604028645965824)]} 0 1
[junit4:junit4] 2> 270669 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[b!53 (1435604028645965824)]} 0 5
[junit4:junit4] 2> 270673 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[c!54 (1435604028653305856)]} 0 1
[junit4:junit4] 2> 270683 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1435604028661694464)]} 0 1
[junit4:junit4] 2> 270684 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1435604028661694464)]} 0 5
[junit4:junit4] 2> 270685 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[c!54]} 0 9
[junit4:junit4] 2> 270689 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[d!55 (1435604028670083072)]} 0 1
[junit4:junit4] 2> 270699 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1435604028678471680)]} 0 1
[junit4:junit4] 2> 270700 T492 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1435604028678471680)]} 0 5
[junit4:junit4] 2> 270701 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[d!55]} 0 9
[junit4:junit4] 2> 270705 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[e!56 (1435604028687908864)]} 0 1
[junit4:junit4] 2> 270715 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1435604028695248896)]} 0 1
[junit4:junit4] 2> 270716 T492 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1435604028695248896)]} 0 5
[junit4:junit4] 2> 270717 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[e!56]} 0 9
[junit4:junit4] 2> 270721 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[f!57 (1435604028704686080)]} 0 1
[junit4:junit4] 2> 270728 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1435604028707831808)]} 0 1
[junit4:junit4] 2> 270729 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[f!57 (1435604028707831808)]} 0 5
[junit4:junit4] 2> 270733 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[g!58 (1435604028716220416)]} 0 1
[junit4:junit4] 2> 270744 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1435604028725657600)]} 0 1
[junit4:junit4] 2> 270745 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1435604028725657600)]} 0 5
[junit4:junit4] 2> 270746 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[g!58]} 0 9
[junit4:junit4] 2> 270750 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[h!59 (1435604028735094784)]} 0 1
[junit4:junit4] 2> 270760 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1435604028742434816)]} 0 1
[junit4:junit4] 2> 270761 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!59 (1435604028742434816)]} 0 5
[junit4:junit4] 2> 270762 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[h!59]} 0 9
[junit4:junit4] 2> 270766 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[i!60 (1435604028751872000)]} 0 1
[junit4:junit4] 2> 270773 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1435604028755017728)]} 0 1
[junit4:junit4] 2> 270774 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[i!60 (1435604028755017728)]} 0 5
[junit4:junit4] 2> 270778 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[j!61 (1435604028763406336)]} 0 1
[junit4:junit4] 2> 270785 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1435604028767600640)]} 0 1
[junit4:junit4] 2> 270786 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[j!61 (1435604028767600640)]} 0 5
[junit4:junit4] 2> 270790 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[k!62 (1435604028777037824)]} 0 1
[junit4:junit4] 2> 270801 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1435604028784377856)]} 0 1
[junit4:junit4] 2> 270802 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!62 (1435604028784377856)]} 0 6
[junit4:junit4] 2> 270803 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[k!62]} 0 10
[junit4:junit4] 2> 270807 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[l!63 (1435604028794863616)]} 0 1
[junit4:junit4] 2> 270814 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1435604028798009344)]} 0 1
[junit4:junit4] 2> 270815 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[l!63 (1435604028798009344)]} 0 5
[junit4:junit4] 2> 270819 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[m!64 (1435604028806397952)]} 0 1
[junit4:junit4] 2> 270826 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!64 (1435604028810592256)]} 0 1
[junit4:junit4] 2> 270827 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[m!64 (1435604028810592256)]} 0 5
[junit4:junit4] 2> 270832 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[n!65 (1435604028821078016)]} 0 1
[junit4:junit4] 2> 270843 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!65 (1435604028828418048)]} 0 1
[junit4:junit4] 2> 270844 T474 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!65 (1435604028828418048)]} 0 6
[junit4:junit4] 2> 270845 T490 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[n!65]} 0 10
[junit4:junit4] 2> 270849 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[o!66 (1435604028838903808)]} 0 1
[junit4:junit4] 2> 270859 T519 C19 P42737 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42730/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!66 (1435604028846243840)]} 0 1
[junit4:junit4] 2> 270860 T492 C21 P42730 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!66 (1435604028846243840)]} 0 5
[junit4:junit4] 2> 270861 T476 C20 P42727 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[o!66]} 0 9
[junit4:junit4] 2> 270865 T450 C22 P42723 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={wt=javabin&version=2} {add=[p!67 (1435604028855681024)]} 0 1
[junit4:junit4] 2> 270876 T504 C18 P42733 oasup.LogUpdateProcessor.finish [collection1] webapp=/bmn path=/update params={distrib.from=http://127.0.0.1:42727/bmn/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add
[...truncated too long message...]
2> 1854590 T4565 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1854590 T4565 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369100063793/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369100063793/jetty4/index;done=false>>]
[junit4:junit4] 2> 1854591 T4565 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369100063793/jetty4/index
[junit4:junit4] 2> 1854591 T4565 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369100063793/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369100063793/jetty4;done=false>>]
[junit4:junit4] 2> 1854591 T4565 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369100063793/jetty4
[junit4:junit4] 2> 1854591 T4565 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1854592 T4565 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89725341781458956-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> 1854593 T4565 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> 1854593 T4565 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1854593 T4565 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1854593 T4565 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> 1854593 T4565 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1854594 T4565 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=CheapBastard, sim=DefaultSimilarity, locale=fi, timezone=America/Nipigon
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=3,free=409279344,total=536870912
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestFiltering, TestQuerySenderNoQuery, TestSolrQueryParserDefaultOperatorResource, TestLuceneMatchVersion, OutputWriterTest, TestComponentsName, TestRecovery, NumericFieldsTest, BadIndexSchemaTest, OpenExchangeRatesOrgProviderTest, DateMathParserTest, TestMaxScoreQueryParser, TestDefaultSimilarityFactory, TestSolrXml, TestCSVLoader, SpellPossibilityIteratorTest, TestDefaultSearchFieldResource, LeaderElectionIntegrationTest, TestOmitPositions, TestHashPartitioner, CachingDirectoryFactoryTest, FullSolrCloudDistribCmdsTest, TestUpdate, TestRandomFaceting, TestCSVResponseWriter, TestNumberUtils, CopyFieldTest, SolrRequestParserTest, SignatureUpdateProcessorFactoryTest, FieldAnalysisRequestHandlerTest, TestAddFieldRealTimeGet, SolrCmdDistributorTest, XsltUpdateRequestHandlerTest, TestJmxMonitoredMap, ClusterStateTest, TestSolrJ, TestSchemaNameResource, JSONWriterTest, TestReload, TimeZoneUtilsTest, TestRangeQuery, TestCoreDiscovery, DistanceFunctionTest, TestWordDelimiterFilterFactory, NoCacheHeaderTest, TestStressLucene, TestJmxIntegration, SpellCheckComponentTest, NotRequiredUniqueKeyTest, SuggesterTSTTest, TestBinaryResponseWriter, SolrIndexConfigTest, PathHierarchyTokenizerFactoryTest, SolrCoreCheckLockOnStartupTest, CoreContainerCoreInitFailuresTest, HighlighterTest, CurrencyFieldXmlFileTest, ZkSolrClientTest, TestLMJelinekMercerSimilarityFactory, BasicZkTest, TestStressReorder, DocumentAnalysisRequestHandlerTest, TestDFRSimilarityFactory, TestPropInject, TestSerializedLuceneMatchVersion, DirectUpdateHandlerTest, TestCollationField, TestElisionMultitermQuery, TestQueryTypes, BasicDistributedZkTest, ChaosMonkeySafeLeaderTest, BasicDistributedZk2Test, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest, TestReplicationHandler, ShardRoutingCustomTest, SliceStateUpdateTest, TestDistributedSearch, AutoCommitTest, TermVectorComponentDistributedTest, TestRealTimeGet, HardAutoCommitTest, DistributedTermsComponentTest, TestSolr4Spatial, StatsComponentTest, PeerSyncTest, ConvertedLegacyTest, TestSort, TestFunctionQuery, BasicFunctionalityTest, TestBadConfig, TestIndexSearcher, CurrencyFieldOpenExchangeTest, SimplePostToolTest, AnalysisAfterCoreReloadTest, TestExtendedDismaxParser, SpellCheckCollatorTest, DocValuesTest, SpatialFilterTest, PolyFieldTest, TestAtomicUpdateErrorCases, StatelessScriptUpdateProcessorFactoryTest, DocValuesMultiTest, IndexBasedSpellCheckerTest, DisMaxRequestHandlerTest, DirectSolrSpellCheckerTest, TermsComponentTest, TestValueSourceCache, TestIndexingPerformance, MoreLikeThisHandlerTest, TestArbitraryIndexDir, SolrPluginUtilsTest, UpdateRequestProcessorFactoryTest, UniqFieldsUpdateProcessorFactoryTest, TestPartialUpdateDeduplication, SearchHandlerTest, SOLR749Test, IndexReaderFactoryTest, AlternateDirectoryTest, BadComponentTest, MultiTermTest, TestDocSet, MinimalSchemaTest, TestPostingsSolrHighlighter, TestCharFilters, TestSweetSpotSimilarityFactory, TestIBSimilarityFactory, TestFastWriter, TestFastOutputStream, ScriptEngineTest, PluginInfoTest, TestSolrXMLSerializer, TestSuggestSpellingConverter, SpellingQueryConverterTest, RAMDirectoryFactoryTest, TestDocumentBuilder, FileUtilsTest, SolrTestCaseJ4Test, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 211.35s, 1 test, 1 error <<< FAILURES!
[...truncated 11 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:380: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:360: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:1240: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:884: There were test failures: 295 suites, 1231 tests, 2 errors, 13 ignored (7 assumptions)
Total time: 51 minutes 24 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure