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/06/08 01:21:26 UTC
[JENKINS] Lucene-Solr-Tests-trunk-Java7 - Build # 4047 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java7/4047/
2 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:47411/zd/j 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:47411/zd/j returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([3C27E9A2B19E217:8224F0825C46822B]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
at org.apache.solr.cloud.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)
FAILED: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:28582/iy/p 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:28582/iy/p returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([3C27E9A2B19E217:8224F0825C46822B]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java: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 9452 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 104901 T255 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /zd/j
[junit4:junit4] 2> 104909 T255 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/J1/./solrtest-ChaosMonkeyShardSplitTest-1370645323122
[junit4:junit4] 2> 104911 T255 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 104912 T256 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 105013 T255 oasc.ZkTestServer.run start zk server on port:47391
[junit4:junit4] 2> 105018 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 105032 T262 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@23ca25c4 name:ZooKeeperConnection Watcher:127.0.0.1:47391 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 105032 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 105033 T255 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 105039 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 105041 T264 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7816c655 name:ZooKeeperConnection Watcher:127.0.0.1:47391/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 105042 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 105042 T255 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 105053 T255 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 105058 T255 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 105063 T255 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 105069 T255 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> 105069 T255 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 105083 T255 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> 105084 T255 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 105191 T255 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> 105192 T255 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 105197 T255 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> 105198 T255 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 105204 T255 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> 105204 T255 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 105210 T255 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> 105210 T255 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 105216 T255 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> 105217 T255 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 105222 T255 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> 105223 T255 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 105228 T255 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> 105229 T255 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 105504 T255 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 105509 T255 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47395
[junit4:junit4] 2> 105510 T255 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 105511 T255 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 105511 T255 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/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370645323447
[junit4:junit4] 2> 105512 T255 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/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370645323447/solr.xml
[junit4:junit4] 2> 105512 T255 oasc.CoreContainer.<init> New CoreContainer 1598493063
[junit4:junit4] 2> 105513 T255 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370645323447/'
[junit4:junit4] 2> 105514 T255 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370645323447/'
[junit4:junit4] 2> 105640 T255 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 105641 T255 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 105642 T255 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 105643 T255 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 105643 T255 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 105644 T255 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 105644 T255 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 105645 T255 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 105645 T255 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 105646 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 105666 T255 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 105667 T255 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47391/solr
[junit4:junit4] 2> 105667 T255 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 105668 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 105672 T275 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3135fbbd name:ZooKeeperConnection Watcher:127.0.0.1:47391 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 105672 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 105676 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 105691 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 105694 T277 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@667893e5 name:ZooKeeperConnection Watcher:127.0.0.1:47391/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 105694 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 105697 T255 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 105709 T255 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 105715 T255 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 105719 T255 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47395_zd%2Fj
[junit4:junit4] 2> 105721 T255 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47395_zd%2Fj
[junit4:junit4] 2> 105727 T255 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 105742 T255 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 105752 T255 oasc.Overseer.start Overseer (id=89826611896582147-127.0.0.1:47395_zd%2Fj-n_0000000000) starting
[junit4:junit4] 2> 105759 T255 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 105771 T279 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 105773 T255 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 105777 T255 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 105780 T255 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 105786 T278 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 105789 T280 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370645323447/collection1
[junit4:junit4] 2> 105790 T280 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 105791 T280 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 105791 T280 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 105794 T280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370645323447/collection1/'
[junit4:junit4] 2> 105795 T280 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370645323447/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 105796 T280 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370645323447/collection1/lib/README' to classloader
[junit4:junit4] 2> 105849 T280 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 105909 T280 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 106011 T280 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 106018 T280 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 106612 T280 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 106616 T280 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 106619 T280 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 106625 T280 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 106670 T280 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 106670 T280 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370645323447/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/control/data/
[junit4:junit4] 2> 106671 T280 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5c47e1f4
[junit4:junit4] 2> 106671 T280 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 106672 T280 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/control/data
[junit4:junit4] 2> 106673 T280 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/control/data/index/
[junit4:junit4] 2> 106673 T280 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 106673 T280 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/control/data/index
[junit4:junit4] 2> 106678 T280 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@69edab40 lockFactory=org.apache.lucene.store.NativeFSLockFactory@344f6a86),segFN=segments_1,generation=1}
[junit4:junit4] 2> 106678 T280 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 106682 T280 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 106682 T280 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 106683 T280 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 106684 T280 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 106684 T280 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 106684 T280 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 106685 T280 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 106686 T280 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 106686 T280 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 106701 T280 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 106709 T280 oass.SolrIndexSearcher.<init> Opening Searcher@c660c0d main
[junit4:junit4] 2> 106709 T280 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/control/data/tlog
[junit4:junit4] 2> 106710 T280 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 106711 T280 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 106715 T281 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c660c0d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 106717 T280 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 106717 T280 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 107292 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 107294 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:47395_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47395/zd/j"}
[junit4:junit4] 2> 107294 T278 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 107300 T278 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 107345 T277 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> 107721 T280 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 107721 T280 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47395/zd/j collection:control_collection shard:shard1
[junit4:junit4] 2> 107723 T280 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 107743 T280 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 107754 T280 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 107755 T280 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 107755 T280 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47395/zd/j/collection1/
[junit4:junit4] 2> 107755 T280 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 107756 T280 oasc.SyncStrategy.syncToMe http://127.0.0.1:47395/zd/j/collection1/ has no replicas
[junit4:junit4] 2> 107756 T280 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47395/zd/j/collection1/
[junit4:junit4] 2> 107756 T280 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 108853 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 108898 T277 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> 108941 T280 oasc.ZkController.register We are http://127.0.0.1:47395/zd/j/collection1/ and leader is http://127.0.0.1:47395/zd/j/collection1/
[junit4:junit4] 2> 108941 T280 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47395/zd/j
[junit4:junit4] 2> 108941 T280 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 108942 T280 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 108942 T280 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 108945 T280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 108947 T255 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 108947 T255 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 109044 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 109077 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 109085 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 109087 T284 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1158cf1 name:ZooKeeperConnection Watcher:127.0.0.1:47391/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 109088 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 109090 T255 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 109097 T255 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 109371 T255 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 109375 T255 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47411
[junit4:junit4] 2> 109376 T255 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 109376 T255 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 109377 T255 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/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370645327309
[junit4:junit4] 2> 109378 T255 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/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370645327309/solr.xml
[junit4:junit4] 2> 109378 T255 oasc.CoreContainer.<init> New CoreContainer 1938511429
[junit4:junit4] 2> 109379 T255 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370645327309/'
[junit4:junit4] 2> 109380 T255 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370645327309/'
[junit4:junit4] 2> 109513 T255 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 109514 T255 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 109515 T255 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 109515 T255 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 109516 T255 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 109517 T255 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 109517 T255 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 109518 T255 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 109518 T255 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 109519 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 109538 T255 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 109539 T255 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47391/solr
[junit4:junit4] 2> 109539 T255 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 109541 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 109544 T295 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4f55423a name:ZooKeeperConnection Watcher:127.0.0.1:47391 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 109545 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 109597 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 109611 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 109614 T297 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c2e7808 name:ZooKeeperConnection Watcher:127.0.0.1:47391/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 109615 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 109663 T255 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 110415 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 110417 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:47395_zd%2Fj_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:47395_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47395/zd/j"}
[junit4:junit4] 2> 110458 T277 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> 110458 T284 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> 110458 T297 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> 110670 T255 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47411_zd%2Fj
[junit4:junit4] 2> 110672 T255 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47411_zd%2Fj
[junit4:junit4] 2> 110676 T277 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 110677 T284 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 110677 T297 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 110678 T284 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> 110678 T297 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> 110679 T277 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 110699 T298 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370645327309/collection1
[junit4:junit4] 2> 110700 T298 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 110701 T298 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 110701 T298 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 110704 T298 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370645327309/collection1/'
[junit4:junit4] 2> 110705 T298 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370645327309/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 110706 T298 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370645327309/collection1/lib/README' to classloader
[junit4:junit4] 2> 110761 T298 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 110826 T298 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 110929 T298 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 110936 T298 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 111519 T298 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 111523 T298 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 111526 T298 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 111532 T298 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 111590 T298 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 111591 T298 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370645327309/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty1/
[junit4:junit4] 2> 111591 T298 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5c47e1f4
[junit4:junit4] 2> 111592 T298 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 111593 T298 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty1
[junit4:junit4] 2> 111593 T298 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty1/index/
[junit4:junit4] 2> 111593 T298 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 111594 T298 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty1/index
[junit4:junit4] 2> 111599 T298 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1334b71d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f4cc38),segFN=segments_1,generation=1}
[junit4:junit4] 2> 111599 T298 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 111603 T298 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 111604 T298 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 111604 T298 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 111605 T298 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 111606 T298 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 111606 T298 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 111607 T298 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 111608 T298 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 111608 T298 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 111624 T298 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 111631 T298 oass.SolrIndexSearcher.<init> Opening Searcher@50e1ff71 main
[junit4:junit4] 2> 111632 T298 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty1/tlog
[junit4:junit4] 2> 111633 T298 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 111633 T298 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 111639 T299 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@50e1ff71 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 111642 T298 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 111642 T298 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 111966 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 111967 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:47411_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47411/zd/j"}
[junit4:junit4] 2> 111967 T278 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 111968 T278 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 111982 T277 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> 111982 T284 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> 111982 T297 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> 112645 T298 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 112645 T298 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47411/zd/j collection:collection1 shard:shard1
[junit4:junit4] 2> 112647 T298 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 112666 T298 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 112677 T298 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 112678 T298 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 112678 T298 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47411/zd/j/collection1/
[junit4:junit4] 2> 112678 T298 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 112679 T298 oasc.SyncStrategy.syncToMe http://127.0.0.1:47411/zd/j/collection1/ has no replicas
[junit4:junit4] 2> 112679 T298 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47411/zd/j/collection1/
[junit4:junit4] 2> 112680 T298 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 113490 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 113536 T277 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> 113536 T284 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> 113536 T297 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> 113616 T298 oasc.ZkController.register We are http://127.0.0.1:47411/zd/j/collection1/ and leader is http://127.0.0.1:47411/zd/j/collection1/
[junit4:junit4] 2> 113616 T298 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47411/zd/j
[junit4:junit4] 2> 113616 T298 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 113617 T298 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 113617 T298 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 113620 T298 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 113622 T255 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 113623 T255 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 113624 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 113909 T255 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 113913 T255 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:15792
[junit4:junit4] 2> 113914 T255 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 113914 T255 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 113915 T255 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/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370645331853
[junit4:junit4] 2> 113916 T255 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/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370645331853/solr.xml
[junit4:junit4] 2> 113916 T255 oasc.CoreContainer.<init> New CoreContainer 1821244856
[junit4:junit4] 2> 113917 T255 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370645331853/'
[junit4:junit4] 2> 113918 T255 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370645331853/'
[junit4:junit4] 2> 114046 T255 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 114047 T255 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 114048 T255 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 114048 T255 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 114049 T255 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 114050 T255 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 114050 T255 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 114051 T255 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 114051 T255 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 114052 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 114070 T255 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 114071 T255 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47391/solr
[junit4:junit4] 2> 114071 T255 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 114073 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 114076 T311 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6dc9aeff name:ZooKeeperConnection Watcher:127.0.0.1:47391 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 114077 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 114080 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 114094 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 114097 T313 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@60e2e7be name:ZooKeeperConnection Watcher:127.0.0.1:47391/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 114097 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 114105 T255 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 115085 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 115087 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:47411_zd%2Fj_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:47411_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47411/zd/j"}
[junit4:junit4] 2> 115104 T313 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> 115104 T284 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> 115104 T297 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> 115104 T277 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> 115110 T255 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:15792_zd%2Fj
[junit4:junit4] 2> 115113 T255 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:15792_zd%2Fj
[junit4:junit4] 2> 115116 T277 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> 115117 T297 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 115117 T284 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 115117 T313 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 115118 T284 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> 115117 T297 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> 115118 T313 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> 115119 T277 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 115127 T314 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370645331853/collection1
[junit4:junit4] 2> 115127 T314 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 115128 T314 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 115129 T314 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 115131 T314 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370645331853/collection1/'
[junit4:junit4] 2> 115133 T314 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370645331853/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 115133 T314 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370645331853/collection1/lib/README' to classloader
[junit4:junit4] 2> 115186 T314 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 115245 T314 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 115347 T314 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 115354 T314 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 115910 T314 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 115914 T314 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 115917 T314 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 115923 T314 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 115969 T314 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 115969 T314 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370645331853/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty2/
[junit4:junit4] 2> 115970 T314 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5c47e1f4
[junit4:junit4] 2> 115971 T314 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 115972 T314 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty2
[junit4:junit4] 2> 115972 T314 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty2/index/
[junit4:junit4] 2> 115972 T314 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 115973 T314 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty2/index
[junit4:junit4] 2> 115977 T314 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@49e2f3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54a93482),segFN=segments_1,generation=1}
[junit4:junit4] 2> 115977 T314 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 115981 T314 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 115982 T314 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 115982 T314 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 115983 T314 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 115984 T314 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 115984 T314 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 115985 T314 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 115986 T314 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 115986 T314 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 116003 T314 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 116010 T314 oass.SolrIndexSearcher.<init> Opening Searcher@40869efe main
[junit4:junit4] 2> 116011 T314 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty2/tlog
[junit4:junit4] 2> 116012 T314 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 116012 T314 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 116018 T315 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@40869efe main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 116021 T314 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 116022 T314 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 116612 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 116614 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:15792_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:15792/zd/j"}
[junit4:junit4] 2> 116614 T278 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 116614 T278 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 116656 T313 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> 116656 T284 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> 116656 T297 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> 116656 T277 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> 117028 T314 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 117028 T314 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:15792/zd/j collection:collection1 shard:shard2
[junit4:junit4] 2> 117030 T314 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 117054 T314 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 117059 T314 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 117060 T314 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 117060 T314 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:15792/zd/j/collection1/
[junit4:junit4] 2> 117060 T314 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 117061 T314 oasc.SyncStrategy.syncToMe http://127.0.0.1:15792/zd/j/collection1/ has no replicas
[junit4:junit4] 2> 117061 T314 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:15792/zd/j/collection1/
[junit4:junit4] 2> 117062 T314 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 118165 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 118188 T313 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> 118188 T284 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> 118188 T297 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> 118188 T277 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> 118200 T314 oasc.ZkController.register We are http://127.0.0.1:15792/zd/j/collection1/ and leader is http://127.0.0.1:15792/zd/j/collection1/
[junit4:junit4] 2> 118200 T314 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:15792/zd/j
[junit4:junit4] 2> 118200 T314 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 118201 T314 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 118201 T314 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 118204 T314 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 118206 T255 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 118206 T255 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 118207 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 118492 T255 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 118496 T255 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:11581
[junit4:junit4] 2> 118497 T255 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 118498 T255 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 118498 T255 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/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370645336436
[junit4:junit4] 2> 118499 T255 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/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370645336436/solr.xml
[junit4:junit4] 2> 118500 T255 oasc.CoreContainer.<init> New CoreContainer 866237125
[junit4:junit4] 2> 118500 T255 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370645336436/'
[junit4:junit4] 2> 118501 T255 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370645336436/'
[junit4:junit4] 2> 118628 T255 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 118629 T255 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 118629 T255 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 118630 T255 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 118630 T255 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 118631 T255 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 118632 T255 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 118632 T255 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 118633 T255 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 118633 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 118651 T255 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 118652 T255 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47391/solr
[junit4:junit4] 2> 118653 T255 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 118654 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 118819 T327 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1813dee3 name:ZooKeeperConnection Watcher:127.0.0.1:47391 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 118819 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 118835 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 118848 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 118851 T329 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@63ed96d8 name:ZooKeeperConnection Watcher:127.0.0.1:47391/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 118852 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 118865 T255 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 119703 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 119705 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:15792_zd%2Fj_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:15792_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:15792/zd/j"}
[junit4:junit4] 2> 119724 T313 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> 119725 T329 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> 119724 T284 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> 119724 T297 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> 119724 T277 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> 119872 T255 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:11581_zd%2Fj
[junit4:junit4] 2> 119874 T255 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:11581_zd%2Fj
[junit4:junit4] 2> 119877 T277 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> 119877 T329 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> 119878 T313 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 119878 T284 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 119878 T297 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 119879 T284 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> 119878 T313 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> 119879 T297 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> 119880 T277 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 119881 T329 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 119888 T330 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370645336436/collection1
[junit4:junit4] 2> 119889 T330 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 119890 T330 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 119890 T330 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 119893 T330 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370645336436/collection1/'
[junit4:junit4] 2> 119895 T330 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370645336436/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 119895 T330 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370645336436/collection1/lib/README' to classloader
[junit4:junit4] 2> 119954 T330 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 120019 T330 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 120122 T330 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 120129 T330 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 120738 T330 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 120743 T330 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 120745 T330 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 120752 T330 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 120800 T330 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 120801 T330 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370645336436/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty3/
[junit4:junit4] 2> 120801 T330 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5c47e1f4
[junit4:junit4] 2> 120802 T330 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 120803 T330 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty3
[junit4:junit4] 2> 120803 T330 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty3/index/
[junit4:junit4] 2> 120804 T330 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 120805 T330 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty3/index
[junit4:junit4] 2> 120809 T330 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2001ff lockFactory=org.apache.lucene.store.NativeFSLockFactory@2b688e15),segFN=segments_1,generation=1}
[junit4:junit4] 2> 120810 T330 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 120814 T330 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 120814 T330 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 120815 T330 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 120816 T330 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 120817 T330 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 120817 T330 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 120818 T330 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 120818 T330 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 120819 T330 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 120838 T330 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 120847 T330 oass.SolrIndexSearcher.<init> Opening Searcher@731a01b main
[junit4:junit4] 2> 120847 T330 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty3/tlog
[junit4:junit4] 2> 120849 T330 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 120849 T330 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 120855 T331 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@731a01b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 120858 T330 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 120858 T330 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 121233 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 121235 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:11581_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:11581/zd/j"}
[junit4:junit4] 2> 121235 T278 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 121235 T278 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 121248 T313 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> 121249 T284 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> 121249 T297 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> 121249 T329 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> 121248 T277 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> 121866 T330 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 121866 T330 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:11581/zd/j collection:collection1 shard:shard1
[junit4:junit4] 2> 121887 T330 oasc.ZkController.register We are http://127.0.0.1:11581/zd/j/collection1/ and leader is http://127.0.0.1:47411/zd/j/collection1/
[junit4:junit4] 2> 121887 T330 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:11581/zd/j
[junit4:junit4] 2> 121888 T330 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 121888 T330 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C48 name=collection1 org.apache.solr.core.SolrCore@2774f915 url=http://127.0.0.1:11581/zd/j/collection1 node=127.0.0.1:11581_zd%2Fj C48_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:11581_zd%2Fj, base_url=http://127.0.0.1:11581/zd/j}
[junit4:junit4] 2> 121896 T332 C48 P11581 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 121897 T330 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 121897 T332 C48 P11581 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 121898 T332 C48 P11581 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 121898 T332 C48 P11581 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 121899 T255 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 121900 T255 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 121900 T332 C48 P11581 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 121901 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 122313 T255 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 122317 T255 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:41886
[junit4:junit4] 2> 122318 T255 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 122319 T255 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 122319 T255 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/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370645340134
[junit4:junit4] 2> 122320 T255 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/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370645340134/solr.xml
[junit4:junit4] 2> 122320 T255 oasc.CoreContainer.<init> New CoreContainer 922164973
[junit4:junit4] 2> 122321 T255 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370645340134/'
[junit4:junit4] 2> 122322 T255 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370645340134/'
[junit4:junit4] 2> 122499 T255 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 122500 T255 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 122501 T255 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 122501 T255 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 122502 T255 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 122502 T255 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 122503 T255 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 122504 T255 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 122504 T255 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 122505 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 122529 T255 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 122530 T255 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:47391/solr
[junit4:junit4] 2> 122530 T255 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 122532 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 122536 T344 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7b43897c name:ZooKeeperConnection Watcher:127.0.0.1:47391 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 122537 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 122540 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 122555 T255 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 122558 T346 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@602d5a26 name:ZooKeeperConnection Watcher:127.0.0.1:47391/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 122558 T255 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 122572 T255 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 122756 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 122757 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:11581_zd%2Fj_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:11581_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:11581/zd/j"}
[junit4:junit4] 2> 122771 T313 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> 122771 T346 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> 122771 T329 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> 122771 T284 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> 122771 T297 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> 122771 T277 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> 123214 T287 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:11581_zd%2Fj_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 123216 T287 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:11581_zd%2Fj_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 0 seconds.
[junit4:junit4] 2> 123217 T287 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:11581_zd%252Fj_collection1&state=recovering&nodeName=127.0.0.1:11581_zd%252Fj&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=4
[junit4:junit4] 2> 123577 T255 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41886_zd%2Fj
[junit4:junit4] 2> 123606 T255 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41886_zd%2Fj
[junit4:junit4] 2> 123610 T277 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> 123611 T346 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123611 T313 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123611 T297 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123611 T284 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123610 T329 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> 123614 T277 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123614 T284 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> 123613 T297 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> 123613 T313 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> 123612 T346 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> 123617 T329 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123622 T347 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370645340134/collection1
[junit4:junit4] 2> 123624 T347 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 123625 T347 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 123625 T347 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 123627 T347 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370645340134/collection1/'
[junit4:junit4] 2> 123629 T347 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370645340134/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 123630 T347 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370645340134/collection1/lib/README' to classloader
[junit4:junit4] 2> 123699 T347 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 123753 T347 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 123855 T347 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 123860 T347 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 124336 T347 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 124339 T347 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 124342 T347 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 124347 T347 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 124384 T347 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 124385 T347 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370645340134/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty4/
[junit4:junit4] 2> 124386 T347 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5c47e1f4
[junit4:junit4] 2> 124386 T347 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 124387 T347 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty4
[junit4:junit4] 2> 124388 T347 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty4/index/
[junit4:junit4] 2> 124388 T347 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 124390 T347 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty4/index
[junit4:junit4] 2> 124395 T347 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4b166521 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1541703c),segFN=segments_1,generation=1}
[junit4:junit4] 2> 124396 T347 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 124400 T347 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 124400 T347 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 124401 T347 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 124402 T347 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 124403 T347 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 124404 T347 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 124405 T347 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 124405 T347 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 124406 T347 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 124419 T347 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 124426 T347 oass.SolrIndexSearcher.<init> Opening Searcher@2b827602 main
[junit4:junit4] 2> 124426 T347 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty4/tlog
[junit4:junit4] 2> 124428 T347 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 124428 T347 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 124433 T348 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2b827602 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 124435 T347 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 124436 T347 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C49 name=collection1 org.apache.solr.core.SolrCore@2774f915 url=http://127.0.0.1:11581/zd/j/collection1 node=127.0.0.1:11581_zd%2Fj C49_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:11581_zd%2Fj, base_url=http://127.0.0.1:11581/zd/j}
[junit4:junit4] 2> 125291 T332 C49 P11581 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:47411/zd/j/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 125303 T332 C49 P11581 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 125331 T332 C49 P11581 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:11581/zd/j START replicas=[http://127.0.0.1:47411/zd/j/collection1/] nUpdates=100
[junit4:junit4] 2> 125344 T332 C49 P11581 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 125345 T332 C49 P11581 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 125345 T332 C49 P11581 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 125346 T332 C49 P11581 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 125346 T332 C49 P11581 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 125346 T332 C49 P11581 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:47411/zd/j/collection1/. core=collection1
[junit4:junit4] 2> 125347 T332 C49 P11581 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C50 name=collection1 org.apache.solr.core.SolrCore@1a787f27 url=http://127.0.0.1:47411/zd/j/collection1 node=127.0.0.1:47411_zd%2Fj C50_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:47411_zd%2Fj, base_url=http://127.0.0.1:47411/zd/j, leader=true}
[junit4:junit4] 2> 125402 T289 C50 P47411 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=8
[junit4:junit4] 2> 125431 T288 C50 P47411 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 125435 T288 C50 P47411 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1334b71d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f4cc38),segFN=segments_1,generation=1}
[junit4:junit4] 2> 125436 T288 C50 P47411 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 125438 T288 C50 P47411 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1334b71d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f4cc38),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1334b71d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f4cc38),segFN=segments_2,generation=2}
[junit4:junit4] 2> 125439 T288 C50 P47411 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 125440 T288 C50 P47411 oass.SolrIndexSearcher.<init> Opening Searcher@61bda00c realtime
[junit4:junit4] 2> 125440 T288 C50 P47411 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 125441 T288 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 47
[junit4:junit4] 2> 125526 T332 C49 P11581 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 125527 T332 C49 P11581 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 2> 125558 T332 C49 P11581 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 125631 T290 C50 P47411 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 125633 T290 C50 P47411 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=71
[junit4:junit4] 2> 125634 T332 C49 P11581 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 125635 T332 C49 P11581 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 125635 T332 C49 P11581 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 125639 T290 C50 P47411 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 125641 T332 C49 P11581 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 125642 T332 C49 P11581 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty3/index.20130607194903852
[junit4:junit4] 2> 125643 T332 C49 P11581 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@61808ee3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@13eaf70c)) fullCopy=false
[junit4:junit4] 2> 125660 T290 C50 P47411 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=6
[junit4:junit4] 2> 125677 T332 C49 P11581 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 125679 T332 C49 P11581 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 125680 T332 C49 P11581 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 125689 T332 C49 P11581 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2001ff lockFactory=org.apache.lucene.store.NativeFSLockFactory@2b688e15),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2001ff lockFactory=org.apache.lucene.store.NativeFSLockFactory@2b688e15),segFN=segments_2,generation=2}
[junit4:junit4] 2> 125689 T332 C49 P11581 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 125690 T332 C49 P11581 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 125690 T332 C49 P11581 oass.SolrIndexSearcher.<init> Opening Searcher@9d71041 main
[junit4:junit4] 2> 125692 T331 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9d71041 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 125693 T332 C49 P11581 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty3/index.20130607194903852 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty3/index.20130607194903852;done=true>>]
[junit4:junit4] 2> 125693 T332 C49 P11581 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty3/index.20130607194903852
[junit4:junit4] 2> 125693 T332 C49 P11581 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty3/index.20130607194903852
[junit4:junit4] 2> 125694 T332 C49 P11581 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 125694 T332 C49 P11581 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 125694 T332 C49 P11581 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 125695 T332 C49 P11581 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 125723 T332 C49 P11581 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 125782 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 125783 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:41886_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41886/zd/j"}
[junit4:junit4] 2> 125784 T278 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 125784 T278 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 125790 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:11581_zd%2Fj_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:11581_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:11581/zd/j"}
[junit4:junit4] 2> 125803 T313 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> 125803 T329 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> 125803 T346 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> 125803 T284 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> 125803 T297 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> 125803 T277 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> 126447 T347 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 126447 T347 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:41886/zd/j collection:collection1 shard:shard2
[junit4:junit4] 2> 126485 T347 oasc.ZkController.register We are http://127.0.0.1:41886/zd/j/collection1/ and leader is http://127.0.0.1:15792/zd/j/collection1/
[junit4:junit4] 2> 126485 T347 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:41886/zd/j
[junit4:junit4] 2> 126485 T347 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 126485 T347 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C51 name=collection1 org.apache.solr.core.SolrCore@408e202 url=http://127.0.0.1:41886/zd/j/collection1 node=127.0.0.1:41886_zd%2Fj C51_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:41886_zd%2Fj, base_url=http://127.0.0.1:41886/zd/j}
[junit4:junit4] 2> 126486 T351 C51 P41886 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 126487 T347 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 126487 T351 C51 P41886 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 126487 T351 C51 P41886 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 126488 T351 C51 P41886 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 126488 T255 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 126489 T255 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 126489 T351 C51 P41886 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 126489 T255 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 126499 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 126500 T303 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:41886_zd%2Fj_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 126501 T255 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 126501 T255 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 126502 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 127318 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 127319 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:41886_zd%2Fj_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:41886_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41886/zd/j"}
[junit4:junit4] 2> 127362 T313 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> 127362 T346 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> 127362 T329 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> 127362 T284 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> 127362 T297 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> 127362 T277 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> 127501 T303 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:41886_zd%2Fj_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 127501 T303 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:41886_zd%252Fj_collection1&state=recovering&nodeName=127.0.0.1:41886_zd%252Fj&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 127505 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 128509 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C51_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:41886_zd%2Fj, base_url=http://127.0.0.1:41886/zd/j}
[junit4:junit4] 2> 129503 T351 C51 P41886 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:15792/zd/j/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 129503 T351 C51 P41886 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:41886/zd/j START replicas=[http://127.0.0.1:15792/zd/j/collection1/] nUpdates=100
[junit4:junit4] 2> 129505 T351 C51 P41886 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 129506 T351 C51 P41886 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 129506 T351 C51 P41886 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 129507 T351 C51 P41886 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 129507 T351 C51 P41886 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 129508 T351 C51 P41886 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:15792/zd/j/collection1/. core=collection1
[junit4:junit4] 2> 129509 T351 C51 P41886 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 129514 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C52 name=collection1 org.apache.solr.core.SolrCore@6b816b0c url=http://127.0.0.1:15792/zd/j/collection1 node=127.0.0.1:15792_zd%2Fj C52_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:15792_zd%2Fj, base_url=http://127.0.0.1:15792/zd/j, leader=true}
[junit4:junit4] 2> 129536 T304 C52 P15792 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 129537 T305 C52 P15792 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 129543 T305 C52 P15792 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@49e2f3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54a93482),segFN=segments_1,generation=1}
[junit4:junit4] 2> 129544 T305 C52 P15792 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 129546 T305 C52 P15792 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@49e2f3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54a93482),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@49e2f3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54a93482),segFN=segments_2,generation=2}
[junit4:junit4] 2> 129546 T305 C52 P15792 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 129547 T305 C52 P15792 oass.SolrIndexSearcher.<init> Opening Searcher@17c55e8a realtime
[junit4:junit4] 2> 129547 T305 C52 P15792 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 129548 T305 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4] 2> 129550 T351 C51 P41886 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 129551 T351 C51 P41886 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 129558 T306 C52 P15792 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 129560 T306 C52 P15792 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=3
[junit4:junit4] 2> 129562 T351 C51 P41886 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 129562 T351 C51 P41886 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 129563 T351 C51 P41886 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 129568 T306 C52 P15792 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 129570 T351 C51 P41886 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 129572 T351 C51 P41886 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty4/index.20130607194907782
[junit4:junit4] 2> 129573 T351 C51 P41886 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6b8e79bf lockFactory=org.apache.lucene.store.NativeFSLockFactory@5e5fb926)) fullCopy=false
[junit4:junit4] 2> 129578 T306 C52 P15792 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 129581 T351 C51 P41886 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 129584 T351 C51 P41886 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 129584 T351 C51 P41886 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 129589 T351 C51 P41886 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4b166521 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1541703c),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4b166521 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1541703c),segFN=segments_2,generation=2}
[junit4:junit4] 2> 129591 T351 C51 P41886 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 129591 T351 C51 P41886 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 129592 T351 C51 P41886 oass.SolrIndexSearcher.<init> Opening Searcher@2a378bdb main
[junit4:junit4] 2> 129594 T348 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2a378bdb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 129595 T351 C51 P41886 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty4/index.20130607194907782 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty4/index.20130607194907782;done=true>>]
[junit4:junit4] 2> 129596 T351 C51 P41886 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty4/index.20130607194907782
[junit4:junit4] 2> 129597 T351 C51 P41886 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370645323121/jetty4/index.20130607194907782
[junit4:junit4] 2> 129597 T351 C51 P41886 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 129598 T351 C51 P41886 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 129598 T351 C51 P41886 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 129599 T351 C51 P41886 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 129602 T351 C51 P41886 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 130375 T278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 130377 T278 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:41886_zd%2Fj_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:41886_zd%2Fj",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41886/zd/j"}
[junit4:junit4] 2> 130395 T313 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> 130396 T329 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> 130396 T346 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> 130396 T297 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> 130396 T277 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> 130395 T284 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> 130520 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 130523 T255 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C53 name=collection1 org.apache.solr.core.SolrCore@6cd7095b url=http://127.0.0.1:47395/zd/j/collection1 node=127.0.0.1:47395_zd%2Fj C53_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:47395_zd%2Fj, base_url=http://127.0.0.1:47395/zd/j, leader=true}
[junit4:junit4] 2> 130536 T267 C53 P47395 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 130539 T267 C53 P47395 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@69edab40 lockFactory=org.apache.lucene.store.NativeFSLockFactory@344f6a86),segFN=segments_1,generation=1}
[junit4:junit4] 2> 130540 T267 C53 P47395 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 130541 T267 C53 P47395 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@69edab40 lockFactory=org.apache.lucene.store.NativeFSLockFactory@344f6a86),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@69edab40 lockFactory=org.apache.lucene.store.NativeFSLockFactory@344f6a86),segFN=segments_2,generation=2}
[junit4:junit4] 2> 130542 T267 C53 P47395 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 130542 T267 C53 P47395 oass.SolrIndexSearcher.<init> Opening Searcher@a2f9923 main
[junit4:junit4] 2> 130543 T267 C53 P47395 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 130544 T281 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a2f9923 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 130545 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 130576 T307 C52 P15792 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 130578 T307 C52 P15792 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@49e2f3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54a93482),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@49e2f3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54a93482),segFN=segments_3,generation=3}
[junit4:junit4] 2> 130579 T307 C52 P15792 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 130579 T307 C52 P15792 oass.SolrIndexSearcher.<init> Opening Searcher@5d244857 main
[junit4:junit4] 2> 130580 T307 C52 P15792 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 130581 T315 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5d244857 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 130595 T307 C52 P15792 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:47411/zd/j/collection1/, StdNode: http://127.0.0.1:11581/zd/j/collection1/, StdNode: http://127.0.0.1:41886/zd/j/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 130607 T291 C50 P47411 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 130609 T291 C50 P47411 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1334b71d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f4cc38),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1334b71d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f4cc38),segFN=segments_3,generation=3}
[junit4:junit4] 2> 130610 T291 C50 P47411 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 130611 T291 C50 P47411 oass.SolrIndexSearcher.<init> Opening Searcher@c87d2b0 main
[junit4:junit4] 2> 130612 T291 C50 P47411 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 130613 T299 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c87d2b0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 130614 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j 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> C51_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:41886_zd%2Fj, base_url=http://127.0.0.1:41886/zd/j}
[junit4:junit4] 2> 130617 T336 C51 P41886 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 130619 T336 C51 P41886 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4b166521 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1541703c),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4b166521 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1541703c),segFN=segments_3,generation=3}
[junit4:junit4] 2> 130619 T336 C51 P41886 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 130620 T336 C51 P41886 oass.SolrIndexSearcher.<init> Opening Searcher@277e4daa main
[junit4:junit4] 2> C49_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:11581_zd%2Fj, base_url=http://127.0.0.1:11581/zd/j}
[junit4:junit4] 2> 130620 T319 C49 P11581 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 130621 T336 C51 P41886 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 130623 T319 C49 P11581 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2001ff lockFactory=org.apache.lucene.store.NativeFSLockFactory@2b688e15),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a2001ff lockFactory=org.apache.lucene.store.NativeFSLockFactory@2b688e15),segFN=segments_3,generation=3}
[junit4:junit4] 2> 130623 T348 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@277e4daa main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 130623 T319 C49 P11581 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 130624 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j 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> 130625 T319 C49 P11581 oass.SolrIndexSearcher.<init> Opening Searcher@6d839948 main
[junit4:junit4] 2> 130626 T319 C49 P11581 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 130627 T331 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6d839948 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 130628 T319 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 130629 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 53
[junit4:junit4] 2> 130631 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 130695 T292 C50 P47411 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 130699 T320 C49 P11581 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 130705 T308 C52 P15792 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 130711 T337 C51 P41886 oasc.SolrCore.execute [collection1] webapp=/zd/j path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 132810 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437225819590098944)} 0 7
[junit4:junit4] 2> 132830 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={update.distrib=FROMLEADER&_version_=-1437225819598487552&update.from=http://127.0.0.1:47411/zd/j/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437225819598487552)} 0 2
[junit4:junit4] 2> 132835 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={update.distrib=FROMLEADER&_version_=-1437225819611070464&update.from=http://127.0.0.1:15792/zd/j/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437225819611070464)} 0 2
[junit4:junit4] 2> 132836 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1437225819611070464)} 0 8
[junit4:junit4] 2> 132837 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437225819598487552)} 0 22
[junit4:junit4] 2> 132842 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[0 (1437225819624701952)]} 0 1
[junit4:junit4] 2> 132863 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1437225819629944832)]} 0 1
[junit4:junit4] 2> 132864 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[0 (1437225819629944832)]} 0 18
[junit4:junit4] 2> 132870 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[1 (1437225819654062080)]} 0 1
[junit4:junit4] 2> 132879 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1437225819659304960)]} 0 1
[junit4:junit4] 2> 132880 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[1 (1437225819659304960)]} 0 6
[junit4:junit4] 2> 132884 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[2 (1437225819669790720)]} 0 0
[junit4:junit4] 2> 132894 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1437225819675033600)]} 0 1
[junit4:junit4] 2> 132895 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[2 (1437225819675033600)]} 0 6
[junit4:junit4] 2> 132899 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[3 (1437225819685519360)]} 0 0
[junit4:junit4] 2> 132909 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1437225819690762240)]} 0 1
[junit4:junit4] 2> 132910 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[3 (1437225819690762240)]} 0 6
[junit4:junit4] 2> 132914 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[4 (1437225819701248000)]} 0 0
[junit4:junit4] 2> 132924 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1437225819706490880)]} 0 1
[junit4:junit4] 2> 132925 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[4 (1437225819706490880)]} 0 6
[junit4:junit4] 2> 132929 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[5 (1437225819716976640)]} 0 0
[junit4:junit4] 2> 132950 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1437225819732705280)]} 0 1
[junit4:junit4] 2> 132951 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1437225819732705280)]} 0 7
[junit4:junit4] 2> 132952 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[5]} 0 19
[junit4:junit4] 2> 132958 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[6 (1437225819746336768)]} 0 1
[junit4:junit4] 2> 132971 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1437225819755773952)]} 0 1
[junit4:junit4] 2> 132972 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[6 (1437225819755773952)]} 0 6
[junit4:junit4] 2> 132974 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[6]} 0 12
[junit4:junit4] 2> 132978 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[7 (1437225819768356864)]} 0 0
[junit4:junit4] 2> 132988 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1437225819773599744)]} 0 1
[junit4:junit4] 2> 132989 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[7 (1437225819773599744)]} 0 6
[junit4:junit4] 2> 132994 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[8 (1437225819784085504)]} 0 1
[junit4:junit4] 2> 133003 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1437225819789328384)]} 0 1
[junit4:junit4] 2> 133005 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[8 (1437225819789328384)]} 0 7
[junit4:junit4] 2> 133010 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[9 (1437225819800862720)]} 0 1
[junit4:junit4] 2> 133023 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1437225819810299904)]} 0 1
[junit4:junit4] 2> 133024 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[9 (1437225819810299904)]} 0 6
[junit4:junit4] 2> 133025 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[9]} 0 11
[junit4:junit4] 2> 133030 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[10 (1437225819821834240)]} 0 1
[junit4:junit4] 2> 133044 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1437225819831271424)]} 0 1
[junit4:junit4] 2> 133045 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1437225819831271424)]} 0 7
[junit4:junit4] 2> 133047 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[10]} 0 13
[junit4:junit4] 2> 133052 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[11 (1437225819844902912)]} 0 1
[junit4:junit4] 2> 133065 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1437225819854340096)]} 0 1
[junit4:junit4] 2> 133067 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1437225819854340096)]} 0 8
[junit4:junit4] 2> 133068 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[11]} 0 12
[junit4:junit4] 2> 133073 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[12 (1437225819866923008)]} 0 1
[junit4:junit4] 2> 133086 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1437225819876360192)]} 0 1
[junit4:junit4] 2> 133087 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1437225819876360192)]} 0 6
[junit4:junit4] 2> 133088 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[12]} 0 11
[junit4:junit4] 2> 133094 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[13 (1437225819888943104)]} 0 1
[junit4:junit4] 2> 133107 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1437225819898380288)]} 0 1
[junit4:junit4] 2> 133108 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1437225819898380288)]} 0 6
[junit4:junit4] 2> 133110 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[13]} 0 12
[junit4:junit4] 2> 133115 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[14 (1437225819910963200)]} 0 1
[junit4:junit4] 2> 133125 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1437225819916206080)]} 0 1
[junit4:junit4] 2> 133127 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[14 (1437225819916206080)]} 0 8
[junit4:junit4] 2> 133132 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[15 (1437225819928788992)]} 0 1
[junit4:junit4] 2> 133141 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1437225819934031872)]} 0 1
[junit4:junit4] 2> 133142 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[15 (1437225819934031872)]} 0 6
[junit4:junit4] 2> 133148 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[16 (1437225819945566208)]} 0 1
[junit4:junit4] 2> 133157 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1437225819950809088)]} 0 1
[junit4:junit4] 2> 133158 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[16 (1437225819950809088)]} 0 6
[junit4:junit4] 2> 133164 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[17 (1437225819962343424)]} 0 1
[junit4:junit4] 2> 133174 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1437225819967586304)]} 0 2
[junit4:junit4] 2> 133175 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[17 (1437225819967586304)]} 0 7
[junit4:junit4] 2> 133181 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[18 (1437225819981217792)]} 0 1
[junit4:junit4] 2> 133194 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1437225819989606400)]} 0 1
[junit4:junit4] 2> 133195 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1437225819989606400)]} 0 6
[junit4:junit4] 2> 133196 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[18]} 0 10
[junit4:junit4] 2> 133201 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[19 (1437225820001140736)]} 0 1
[junit4:junit4] 2> 133210 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1437225820006383616)]} 0 1
[junit4:junit4] 2> 133211 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[19 (1437225820006383616)]} 0 6
[junit4:junit4] 2> 133215 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[20 (1437225820016869376)]} 0 0
[junit4:junit4] 2> 133228 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1437225820025257984)]} 0 1
[junit4:junit4] 2> 133229 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[20 (1437225820025257984)]} 0 6
[junit4:junit4] 2> 133230 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[20]} 0 11
[junit4:junit4] 2> 133235 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[21 (1437225820036792320)]} 0 1
[junit4:junit4] 2> 133248 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1437225820046229504)]} 0 1
[junit4:junit4] 2> 133249 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[21 (1437225820046229504)]} 0 6
[junit4:junit4] 2> 133250 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[21]} 0 11
[junit4:junit4] 2> 133255 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[22 (1437225820057763840)]} 0 1
[junit4:junit4] 2> 133267 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1437225820066152448)]} 0 1
[junit4:junit4] 2> 133268 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1437225820066152448)]} 0 6
[junit4:junit4] 2> 133269 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[22]} 0 10
[junit4:junit4] 2> 133274 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[23 (1437225820077686784)]} 0 1
[junit4:junit4] 2> 133287 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1437225820087123968)]} 0 1
[junit4:junit4] 2> 133288 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[23 (1437225820087123968)]} 0 6
[junit4:junit4] 2> 133289 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[23]} 0 11
[junit4:junit4] 2> 133294 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[24 (1437225820098658304)]} 0 1
[junit4:junit4] 2> 133303 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1437225820103901184)]} 0 1
[junit4:junit4] 2> 133304 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[24 (1437225820103901184)]} 0 6
[junit4:junit4] 2> 133310 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[25 (1437225820115435520)]} 0 1
[junit4:junit4] 2> 133320 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1437225820121726976)]} 0 1
[junit4:junit4] 2> 133321 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[25 (1437225820121726976)]} 0 6
[junit4:junit4] 2> 133325 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[26 (1437225820132212736)]} 0 1
[junit4:junit4] 2> 133335 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1437225820137455616)]} 0 1
[junit4:junit4] 2> 133336 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[26 (1437225820137455616)]} 0 6
[junit4:junit4] 2> 133340 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[27 (1437225820147941376)]} 0 1
[junit4:junit4] 2> 133353 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1437225820156329984)]} 0 1
[junit4:junit4] 2> 133354 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[27 (1437225820156329984)]} 0 6
[junit4:junit4] 2> 133355 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[27]} 0 11
[junit4:junit4] 2> 133359 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[28 (1437225820167864320)]} 0 0
[junit4:junit4] 2> 133373 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1437225820177301504)]} 0 1
[junit4:junit4] 2> 133374 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[28 (1437225820177301504)]} 0 6
[junit4:junit4] 2> 133375 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[28]} 0 11
[junit4:junit4] 2> 133380 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[29 (1437225820188835840)]} 0 1
[junit4:junit4] 2> 133392 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1437225820197224448)]} 0 1
[junit4:junit4] 2> 133393 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1437225820197224448)]} 0 6
[junit4:junit4] 2> 133394 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[29]} 0 10
[junit4:junit4] 2> 133399 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[30 (1437225820208758784)]} 0 1
[junit4:junit4] 2> 133408 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1437225820214001664)]} 0 1
[junit4:junit4] 2> 133409 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[30 (1437225820214001664)]} 0 6
[junit4:junit4] 2> 133413 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[31 (1437225820224487424)]} 0 1
[junit4:junit4] 2> 133426 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1437225820232876032)]} 0 1
[junit4:junit4] 2> 133427 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[31 (1437225820232876032)]} 0 6
[junit4:junit4] 2> 133428 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[31]} 0 10
[junit4:junit4] 2> 133433 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[32 (1437225820244410368)]} 0 1
[junit4:junit4] 2> 133446 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1437225820253847552)]} 0 1
[junit4:junit4] 2> 133447 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[32 (1437225820253847552)]} 0 6
[junit4:junit4] 2> 133448 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[32]} 0 12
[junit4:junit4] 2> 133452 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[33 (1437225820265381888)]} 0 1
[junit4:junit4] 2> 133466 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1437225820274819072)]} 0 1
[junit4:junit4] 2> 133467 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[33 (1437225820274819072)]} 0 6
[junit4:junit4] 2> 133468 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[33]} 0 11
[junit4:junit4] 2> 133474 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[34 (1437225820287401984)]} 0 1
[junit4:junit4] 2> 133483 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1437225820292644864)]} 0 1
[junit4:junit4] 2> 133484 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[34 (1437225820292644864)]} 0 6
[junit4:junit4] 2> 133488 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[35 (1437225820303130624)]} 0 1
[junit4:junit4] 2> 133498 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1437225820308373504)]} 0 1
[junit4:junit4] 2> 133499 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[35 (1437225820308373504)]} 0 6
[junit4:junit4] 2> 133503 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[36 (1437225820318859264)]} 0 1
[junit4:junit4] 2> 133517 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1437225820328296448)]} 0 1
[junit4:junit4] 2> 133518 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[36 (1437225820328296448)]} 0 6
[junit4:junit4] 2> 133519 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[36]} 0 12
[junit4:junit4] 2> 133524 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[37 (1437225820340879360)]} 0 1
[junit4:junit4] 2> 133537 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1437225820349267968)]} 0 1
[junit4:junit4] 2> 133538 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[37 (1437225820349267968)]} 0 6
[junit4:junit4] 2> 133539 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[37]} 0 10
[junit4:junit4] 2> 133544 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[38 (1437225820360802304)]} 0 1
[junit4:junit4] 2> 133557 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1437225820370239488)]} 0 1
[junit4:junit4] 2> 133558 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[38 (1437225820370239488)]} 0 6
[junit4:junit4] 2> 133559 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[38]} 0 11
[junit4:junit4] 2> 133565 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[39 (1437225820382822400)]} 0 1
[junit4:junit4] 2> 133577 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1437225820391211008)]} 0 1
[junit4:junit4] 2> 133578 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[39 (1437225820391211008)]} 0 6
[junit4:junit4] 2> 133579 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[39]} 0 10
[junit4:junit4] 2> 133585 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[40 (1437225820403793920)]} 0 1
[junit4:junit4] 2> 133598 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1437225820413231104)]} 0 1
[junit4:junit4] 2> 133599 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[40 (1437225820413231104)]} 0 6
[junit4:junit4] 2> 133600 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[40]} 0 11
[junit4:junit4] 2> 133605 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[41 (1437225820424765440)]} 0 1
[junit4:junit4] 2> 133613 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1437225820430008320)]} 0 0
[junit4:junit4] 2> 133615 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[41 (1437225820430008320)]} 0 7
[junit4:junit4] 2> 133620 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[42 (1437225820440494080)]} 0 2
[junit4:junit4] 2> 133629 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1437225820446785536)]} 0 1
[junit4:junit4] 2> 133630 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[42 (1437225820446785536)]} 0 6
[junit4:junit4] 2> 133634 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[43 (1437225820456222720)]} 0 1
[junit4:junit4] 2> 133645 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1437225820463562752)]} 0 1
[junit4:junit4] 2> 133647 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[43 (1437225820463562752)]} 0 6
[junit4:junit4] 2> 133648 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[43]} 0 11
[junit4:junit4] 2> 133653 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[44 (1437225820475097088)]} 0 2
[junit4:junit4] 2> 133661 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1437225820480339968)]} 0 0
[junit4:junit4] 2> 133662 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[44 (1437225820480339968)]} 0 6
[junit4:junit4] 2> 133668 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[45 (1437225820490825728)]} 0 1
[junit4:junit4] 2> 133679 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1437225820499214336)]} 0 1
[junit4:junit4] 2> 133680 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[45 (1437225820499214336)]} 0 5
[junit4:junit4] 2> 133681 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[45]} 0 9
[junit4:junit4] 2> 133685 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[46 (1437225820508651520)]} 0 1
[junit4:junit4] 2> 133696 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1437225820517040128)]} 0 1
[junit4:junit4] 2> 133697 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[46 (1437225820517040128)]} 0 6
[junit4:junit4] 2> 133698 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[46]} 0 10
[junit4:junit4] 2> 133702 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[47 (1437225820527525888)]} 0 1
[junit4:junit4] 2> 133714 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1437225820535914496)]} 0 1
[junit4:junit4] 2> 133715 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[47 (1437225820535914496)]} 0 5
[junit4:junit4] 2> 133716 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[47]} 0 10
[junit4:junit4] 2> 133720 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[48 (1437225820546400256)]} 0 1
[junit4:junit4] 2> 133731 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1437225820553740288)]} 0 1
[junit4:junit4] 2> 133732 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[48 (1437225820553740288)]} 0 6
[junit4:junit4] 2> 133733 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[48]} 0 9
[junit4:junit4] 2> 133737 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[49 (1437225820564226048)]} 0 1
[junit4:junit4] 2> 133744 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1437225820568420352)]} 0 1
[junit4:junit4] 2> 133745 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[49 (1437225820568420352)]} 0 5
[junit4:junit4] 2> 133749 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[50 (1437225820576808960)]} 0 1
[junit4:junit4] 2> 133756 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1437225820581003264)]} 0 1
[junit4:junit4] 2> 133757 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[50 (1437225820581003264)]} 0 5
[junit4:junit4] 2> 133761 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[51 (1437225820589391872)]} 0 1
[junit4:junit4] 2> 133768 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1437225820592537600)]} 0 1
[junit4:junit4] 2> 133769 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[51 (1437225820592537600)]} 0 5
[junit4:junit4] 2> 133773 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[52 (1437225820601974784)]} 0 1
[junit4:junit4] 2> 133780 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1437225820606169088)]} 0 1
[junit4:junit4] 2> 133781 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[52 (1437225820606169088)]} 0 5
[junit4:junit4] 2> 133785 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[53 (1437225820614557696)]} 0 1
[junit4:junit4] 2> 133797 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1437225820622946304)]} 0 1
[junit4:junit4] 2> 133798 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1437225820622946304)]} 0 6
[junit4:junit4] 2> 133799 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[53]} 0 10
[junit4:junit4] 2> 133803 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[54 (1437225820633432064)]} 0 1
[junit4:junit4] 2> 133813 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1437225820640772096)]} 0 1
[junit4:junit4] 2> 133814 T291 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[54 (1437225820640772096)]} 0 5
[junit4:junit4] 2> 133815 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[54]} 0 9
[junit4:junit4] 2> 133821 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[55 (1437225820651257856)]} 0 1
[junit4:junit4] 2> 133829 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1437225820656500736)]} 0 1
[junit4:junit4] 2> 133831 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[55 (1437225820656500736)]} 0 6
[junit4:junit4] 2> 133835 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[56 (1437225820666986496)]} 0 1
[junit4:junit4] 2> 133842 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1437225820670132224)]} 0 1
[junit4:junit4] 2> 133843 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[56 (1437225820670132224)]} 0 5
[junit4:junit4] 2> 133847 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[57 (1437225820678520832)]} 0 1
[junit4:junit4] 2> 133857 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1437225820686909440)]} 0 1
[junit4:junit4] 2> 133858 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[57 (1437225820686909440)]} 0 5
[junit4:junit4] 2> 133859 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[57]} 0 9
[junit4:junit4] 2> 133863 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[58 (1437225820695298048)]} 0 1
[junit4:junit4] 2> 133873 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1437225820702638080)]} 0 1
[junit4:junit4] 2> 133874 T309 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[58 (1437225820702638080)]} 0 5
[junit4:junit4] 2> 133875 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[58]} 0 9
[junit4:junit4] 2> 133879 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[59 (1437225820712075264)]} 0 1
[junit4:junit4] 2> 133886 T321 C49 P11581 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:47411/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1437225820716269568)]} 0 1
[junit4:junit4] 2> 133887 T293 C50 P47411 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[59 (1437225820716269568)]} 0 5
[junit4:junit4] 2> 133891 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[60 (1437225820725706752)]} 0 1
[junit4:junit4] 2> 133898 T336 C51 P41886 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={distrib.from=http://127.0.0.1:15792/zd/j/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1437225820728852480)]} 0 1
[junit4:junit4] 2> 133899 T307 C52 P15792 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[60 (1437225820728852480)]} 0 5
[junit4:junit4] 2> 133903 T267 C53 P47395 oasup.LogUpdateProcessor.finish [collection1] webapp=/zd/j path=/update params={wt=javabin&version=2} {add=[61 (1437225820737241088)]} 0 1
[junit4:junit4] 2> 133910 T321 C49 P11581 oasup.LogUpdateProcessor.finish [c
[...truncated too long message...]
t4:junit4] ERROR 209s J0 | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:28582/iy/p returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([3C27E9A2B19E217:8224F0825C46822B]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 538850 T1251 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 538853 T1325 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 538853 T1325 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> 538853 T1325 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 566473 T1342 oasu.PeerSync.handleResponse WARN PeerSync: core=collection1 url=http://127.0.0.1:15338/iy/p couldn't connect to http://127.0.0.1:20665/iy/p/collection1/, counting as success
[junit4:junit4] 2> 566474 T1342 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:15338/iy/p DONE. sync succeeded
[junit4:junit4] 2> 566474 T1342 oasc.SyncStrategy.syncReplicas We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 2> 566475 T1342 oasc.ShardLeaderElectionContext.rejoinLeaderElection Not rejoining election because CoreContainer is shutdown
[junit4:junit4] 2> 566475 T1342 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@25ebba4b
[junit4:junit4] 2> 566484 T1342 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=758,adds=758,deletesById=369,deletesByQuery=0,errors=0,cumulative_adds=800,cumulative_deletesById=369,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 566484 T1342 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 566485 T1342 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 566485 T1342 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 566508 T1342 C171 P15338 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@277a7b8a lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f4df30d),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@277a7b8a lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f4df30d),segFN=segments_5,generation=5}
[junit4:junit4] 2> 566509 T1342 C171 P15338 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 566514 T1342 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 566515 T1342 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 566515 T1342 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370645546289/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370645546289/jetty4;done=false>>]
[junit4:junit4] 2> 566515 T1342 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370645546289/jetty4
[junit4:junit4] 2> 566515 T1342 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370645546289/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370645546289/jetty4/index;done=false>>]
[junit4:junit4] 2> 566516 T1342 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370645546289/jetty4/index
[junit4:junit4] 2> 566516 T1342 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> 566516 T1342 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 566516 T1342 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 566517 T1342 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> 566517 T1342 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 566517 T1342 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=MockSep), _version_=Pulsing41(freqCutoff=7 minBlockSize=34 maxBlockSize=112), n_ti=Pulsing41(freqCutoff=7 minBlockSize=34 maxBlockSize=112)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=et_EE, timezone=Europe/Tiraspol
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=2,free=201212216,total=368050176
[junit4:junit4] 2> NOTE: All tests run in this JVM: [QueryResultKeyTest, TestPseudoReturnFields, OverseerTest, UnloadDistributedZkTest, TestPHPSerializedResponseWriter, AlternateDirectoryTest, TestBadConfig, BasicFunctionalityTest, TestPerFieldSimilarity, TestIBSimilarityFactory, SolrTestCaseJ4Test, CoreAdminHandlerTest, PeerSyncTest, SearchHandlerTest, TestSolrDeletionPolicy2, RAMDirectoryFactoryTest, TestReloadAndDeleteDocs, BinaryUpdateRequestHandlerTest, TestPropInjectDefaults, TestXIncludeConfig, TestSolrDeletionPolicy1, TestSolrIndexConfig, SOLR749Test, TestSolrCoreProperties, TestLRUCache, PolyFieldTest, OverseerCollectionProcessorTest, TestSchemaResource, ScriptEngineTest, TestSweetSpotSimilarityFactory, TestQuerySenderListener, SuggesterFSTTest, ZkCLITest, StatelessScriptUpdateProcessorFactoryTest, TestReversedWildcardFilterFactory, DistributedQueryElevationComponentTest, PreAnalyzedFieldTest, SimpleFacetsTest, UUIDFieldTest, PrimitiveFieldTypeTest, TestValueSourceCache, DocValuesTest, RegexBoostProcessorTest, TestFunctionQuery, TestExtendedDismaxParser, TestPluginEnable, TestCloudManagedSchema, TestFaceting, SolrCoreTest, CacheHeaderTest, ExternalFileFieldSortTest, LoggingHandlerTest, LegacyHTMLStripCharFilterTest, ResponseLogComponentTest, TestPhraseSuggestions, DocumentBuilderTest, ShardSplitTest]
[junit4:junit4] Completed on J0 in 237.49s, 1 test, 1 error <<< FAILURES!
[...truncated 604 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:385: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:365: 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: 296 suites, 1243 tests, 2 errors, 13 ignored (7 assumptions)
Total time: 54 minutes 39 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure