You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/07 06:40:33 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.7.0_21) - Build # 5953
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5953/
Java: 32bit/jdk1.7.0_21 -server -XX:+UseG1GC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:53916 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:53916 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([6FE8A790C080EF44:EE0E2988B7DF8F78]: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)
Build Log:
[...truncated 9668 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 389281 T2220 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 389287 T2220 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeyShardSplitTest-1370579053955
[junit4:junit4] 2> 389287 T2220 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 389288 T2221 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 389388 T2220 oasc.ZkTestServer.run start zk server on port:44049
[junit4:junit4] 2> 389389 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 389478 T2227 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@22e333 name:ZooKeeperConnection Watcher:127.0.0.1:44049 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 389479 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 389480 T2220 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 389484 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 389485 T2229 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@705b0f name:ZooKeeperConnection Watcher:127.0.0.1:44049/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 389485 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 389485 T2220 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 389487 T2220 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 389488 T2220 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 389489 T2220 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 389491 T2220 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 389491 T2220 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 389494 T2220 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 389494 T2220 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 389496 T2220 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 389497 T2220 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 389498 T2220 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 389499 T2220 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 389500 T2220 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 389500 T2220 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 389502 T2220 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 389503 T2220 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 389504 T2220 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 389505 T2220 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 389506 T2220 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 389506 T2220 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 389508 T2220 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 389509 T2220 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 389585 T2220 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 389597 T2220 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40438
[junit4:junit4] 2> 389598 T2220 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 389598 T2220 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 389599 T2220 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370579054178
[junit4:junit4] 2> 389599 T2220 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370579054178/solr.xml
[junit4:junit4] 2> 389600 T2220 oasc.CoreContainer.<init> New CoreContainer 6618393
[junit4:junit4] 2> 389600 T2220 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370579054178/'
[junit4:junit4] 2> 389600 T2220 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370579054178/'
[junit4:junit4] 2> 389657 T2220 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 389657 T2220 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 389658 T2220 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 389658 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 389658 T2220 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 389659 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 389659 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 389659 T2220 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 389660 T2220 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 389660 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 389663 T2220 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 389664 T2220 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:44049/solr
[junit4:junit4] 2> 389664 T2220 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 389665 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 389666 T2240 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ce72e name:ZooKeeperConnection Watcher:127.0.0.1:44049 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 389666 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 389667 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 389670 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 389671 T2242 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@260def name:ZooKeeperConnection Watcher:127.0.0.1:44049/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 389671 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 389672 T2220 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 389674 T2220 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 389675 T2220 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 389676 T2220 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40438_
[junit4:junit4] 2> 389677 T2220 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40438_
[junit4:junit4] 2> 389679 T2220 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 389682 T2220 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 389683 T2220 oasc.Overseer.start Overseer (id=89822268880125955-127.0.0.1:40438_-n_0000000000) starting
[junit4:junit4] 2> 389685 T2220 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 389688 T2244 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 389688 T2220 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 389690 T2220 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 389691 T2220 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 389693 T2243 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 389697 T2245 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370579054178/collection1
[junit4:junit4] 2> 389697 T2245 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 389697 T2245 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 389698 T2245 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 389698 T2245 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370579054178/collection1/'
[junit4:junit4] 2> 389699 T2245 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370579054178/collection1/lib/README' to classloader
[junit4:junit4] 2> 389699 T2245 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370579054178/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 389723 T2245 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 389754 T2245 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 389755 T2245 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 389758 T2245 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 390042 T2245 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 390044 T2245 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 390046 T2245 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 390048 T2245 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 390062 T2245 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 390062 T2245 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370579054178/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/control/data/
[junit4:junit4] 2> 390063 T2245 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1debd03
[junit4:junit4] 2> 390063 T2245 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 390063 T2245 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/control/data
[junit4:junit4] 2> 390064 T2245 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/control/data/index/
[junit4:junit4] 2> 390064 T2245 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 390064 T2245 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/control/data/index
[junit4:junit4] 2> 390066 T2245 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c88bab lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b54b47),segFN=segments_1,generation=1}
[junit4:junit4] 2> 390066 T2245 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 390068 T2245 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 390068 T2245 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 390069 T2245 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 390069 T2245 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 390069 T2245 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 390070 T2245 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 390070 T2245 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 390070 T2245 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 390071 T2245 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 390073 T2245 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 390075 T2245 oass.SolrIndexSearcher.<init> Opening Searcher@111e359 main
[junit4:junit4] 2> 390076 T2245 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/control/data/tlog
[junit4:junit4] 2> 390076 T2245 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 390076 T2245 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 390079 T2246 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@111e359 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 390080 T2245 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 390080 T2245 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 391195 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 391196 T2243 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:40438_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40438"}
[junit4:junit4] 2> 391196 T2243 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 391196 T2243 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 391200 T2242 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> 392083 T2245 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 392083 T2245 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40438 collection:control_collection shard:shard1
[junit4:junit4] 2> 392084 T2245 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 392090 T2245 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 392093 T2245 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 392093 T2245 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 392094 T2245 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40438/collection1/
[junit4:junit4] 2> 392094 T2245 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 392095 T2245 oasc.SyncStrategy.syncToMe http://127.0.0.1:40438/collection1/ has no replicas
[junit4:junit4] 2> 392095 T2245 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40438/collection1/
[junit4:junit4] 2> 392096 T2245 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 392702 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 392706 T2242 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> 392752 T2245 oasc.ZkController.register We are http://127.0.0.1:40438/collection1/ and leader is http://127.0.0.1:40438/collection1/
[junit4:junit4] 2> 392752 T2245 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40438
[junit4:junit4] 2> 392753 T2245 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 392753 T2245 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 392753 T2245 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 392754 T2245 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 392755 T2220 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 392755 T2220 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 392756 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 392759 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 392760 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 392761 T2249 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@40a7f4 name:ZooKeeperConnection Watcher:127.0.0.1:44049/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 392761 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 392762 T2220 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 392764 T2220 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 392845 T2220 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 392846 T2220 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53916
[junit4:junit4] 2> 392847 T2220 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 392847 T2220 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 392848 T2220 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370579057432
[junit4:junit4] 2> 392848 T2220 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370579057432/solr.xml
[junit4:junit4] 2> 392849 T2220 oasc.CoreContainer.<init> New CoreContainer 7764340
[junit4:junit4] 2> 392849 T2220 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370579057432/'
[junit4:junit4] 2> 392850 T2220 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370579057432/'
[junit4:junit4] 2> 392918 T2220 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 392919 T2220 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 392919 T2220 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 392919 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 392920 T2220 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 392920 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 392921 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 392922 T2220 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 392922 T2220 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 392923 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 392927 T2220 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 392928 T2220 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:44049/solr
[junit4:junit4] 2> 392929 T2220 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 392931 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 392958 T2260 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d4c32 name:ZooKeeperConnection Watcher:127.0.0.1:44049 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 392958 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 392978 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 392981 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 392988 T2262 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6bc81 name:ZooKeeperConnection Watcher:127.0.0.1:44049/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 392988 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 392992 T2220 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 393995 T2220 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53916_
[junit4:junit4] 2> 393996 T2220 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53916_
[junit4:junit4] 2> 393998 T2242 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> 393998 T2249 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 393999 T2262 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 393999 T2242 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 394004 T2263 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370579057432/collection1
[junit4:junit4] 2> 394005 T2263 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 394005 T2263 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 394005 T2263 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 394006 T2263 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370579057432/collection1/'
[junit4:junit4] 2> 394007 T2263 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370579057432/collection1/lib/README' to classloader
[junit4:junit4] 2> 394007 T2263 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370579057432/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 394040 T2263 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 394111 T2263 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 394113 T2263 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 394116 T2263 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 394209 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 394209 T2243 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:40438__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:40438_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40438"}
[junit4:junit4] 2> 394213 T2262 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> 394213 T2242 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> 394213 T2249 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> 394446 T2263 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 394448 T2263 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 394450 T2263 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 394452 T2263 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 394479 T2263 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 394480 T2263 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370579057432/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty1/
[junit4:junit4] 2> 394480 T2263 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1debd03
[junit4:junit4] 2> 394481 T2263 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 394481 T2263 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty1
[junit4:junit4] 2> 394481 T2263 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty1/index/
[junit4:junit4] 2> 394482 T2263 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 394482 T2263 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty1/index
[junit4:junit4] 2> 394484 T2263 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9c25c0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@871745),segFN=segments_1,generation=1}
[junit4:junit4] 2> 394484 T2263 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 394487 T2263 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 394487 T2263 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 394488 T2263 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 394488 T2263 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 394489 T2263 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 394489 T2263 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 394489 T2263 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 394490 T2263 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 394490 T2263 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 394493 T2263 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 394495 T2263 oass.SolrIndexSearcher.<init> Opening Searcher@1a067a8 main
[junit4:junit4] 2> 394496 T2263 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty1/tlog
[junit4:junit4] 2> 394496 T2263 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 394497 T2263 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 394501 T2264 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a067a8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 394503 T2263 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 394503 T2263 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 395716 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 395717 T2243 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:53916_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53916"}
[junit4:junit4] 2> 395717 T2243 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 395717 T2243 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 395719 T2242 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> 395719 T2249 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> 395719 T2262 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> 396505 T2263 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 396505 T2263 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53916 collection:collection1 shard:shard1
[junit4:junit4] 2> 396506 T2263 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 396511 T2263 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 396513 T2263 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 396513 T2263 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 396514 T2263 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53916/collection1/
[junit4:junit4] 2> 396514 T2263 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 396514 T2263 oasc.SyncStrategy.syncToMe http://127.0.0.1:53916/collection1/ has no replicas
[junit4:junit4] 2> 396515 T2263 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53916/collection1/
[junit4:junit4] 2> 396515 T2263 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 397222 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 397226 T2242 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> 397226 T2262 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> 397226 T2249 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> 397273 T2263 oasc.ZkController.register We are http://127.0.0.1:53916/collection1/ and leader is http://127.0.0.1:53916/collection1/
[junit4:junit4] 2> 397273 T2263 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53916
[junit4:junit4] 2> 397274 T2263 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 397274 T2263 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 397274 T2263 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 397276 T2263 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 397277 T2220 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 397278 T2220 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 397278 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 397357 T2220 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 397359 T2220 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35197
[junit4:junit4] 2> 397359 T2220 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 397360 T2220 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 397360 T2220 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370579061950
[junit4:junit4] 2> 397360 T2220 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370579061950/solr.xml
[junit4:junit4] 2> 397361 T2220 oasc.CoreContainer.<init> New CoreContainer 22327507
[junit4:junit4] 2> 397361 T2220 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370579061950/'
[junit4:junit4] 2> 397362 T2220 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370579061950/'
[junit4:junit4] 2> 397405 T2220 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 397406 T2220 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 397406 T2220 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 397406 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 397407 T2220 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 397407 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 397408 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 397408 T2220 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 397408 T2220 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 397409 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 397411 T2220 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 397412 T2220 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:44049/solr
[junit4:junit4] 2> 397412 T2220 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 397413 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 397414 T2276 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c9bfa8 name:ZooKeeperConnection Watcher:127.0.0.1:44049 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 397414 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 397415 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 397418 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 397419 T2278 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5819ca name:ZooKeeperConnection Watcher:127.0.0.1:44049/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 397419 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 397422 T2220 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 398424 T2220 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35197_
[junit4:junit4] 2> 398426 T2220 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35197_
[junit4:junit4] 2> 398429 T2262 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> 398429 T2249 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> 398429 T2242 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> 398432 T2278 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 398433 T2262 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 398435 T2242 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 398436 T2249 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 398442 T2279 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370579061950/collection1
[junit4:junit4] 2> 398442 T2279 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 398442 T2279 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 398443 T2279 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 398443 T2279 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370579061950/collection1/'
[junit4:junit4] 2> 398444 T2279 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370579061950/collection1/lib/README' to classloader
[junit4:junit4] 2> 398444 T2279 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370579061950/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 398470 T2279 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 398502 T2279 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 398503 T2279 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 398507 T2279 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 398729 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 398730 T2243 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53916__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:53916_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53916"}
[junit4:junit4] 2> 398732 T2262 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> 398733 T2278 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> 398732 T2242 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> 398732 T2249 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> 398826 T2279 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 398828 T2279 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 398830 T2279 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 398833 T2279 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 398851 T2279 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 398851 T2279 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370579061950/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty2/
[junit4:junit4] 2> 398851 T2279 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1debd03
[junit4:junit4] 2> 398852 T2279 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 398853 T2279 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty2
[junit4:junit4] 2> 398853 T2279 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty2/index/
[junit4:junit4] 2> 398853 T2279 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 398853 T2279 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty2/index
[junit4:junit4] 2> 398855 T2279 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@130c5b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f95c77),segFN=segments_1,generation=1}
[junit4:junit4] 2> 398855 T2279 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 398856 T2279 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 398857 T2279 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 398857 T2279 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 398858 T2279 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 398858 T2279 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 398858 T2279 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 398858 T2279 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 398859 T2279 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 398859 T2279 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 398861 T2279 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 398864 T2279 oass.SolrIndexSearcher.<init> Opening Searcher@12e4d2d main
[junit4:junit4] 2> 398864 T2279 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty2/tlog
[junit4:junit4] 2> 398864 T2279 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 398865 T2279 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 398868 T2280 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12e4d2d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 398870 T2279 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 398870 T2279 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 400236 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 400236 T2243 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:35197_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35197"}
[junit4:junit4] 2> 400237 T2243 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 400237 T2243 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 400277 T2249 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> 400277 T2242 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> 400277 T2278 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> 400277 T2262 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> 400872 T2279 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 400872 T2279 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35197 collection:collection1 shard:shard2
[junit4:junit4] 2> 400873 T2279 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 400879 T2279 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 400881 T2279 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 400881 T2279 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 400882 T2279 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:35197/collection1/
[junit4:junit4] 2> 400882 T2279 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 400882 T2279 oasc.SyncStrategy.syncToMe http://127.0.0.1:35197/collection1/ has no replicas
[junit4:junit4] 2> 400882 T2279 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:35197/collection1/
[junit4:junit4] 2> 400882 T2279 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 401781 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 401786 T2262 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> 401786 T2249 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> 401786 T2242 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> 401786 T2278 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> 401838 T2279 oasc.ZkController.register We are http://127.0.0.1:35197/collection1/ and leader is http://127.0.0.1:35197/collection1/
[junit4:junit4] 2> 401838 T2279 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35197
[junit4:junit4] 2> 401839 T2279 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 401839 T2279 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 401839 T2279 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 401841 T2279 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 401842 T2220 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 401843 T2220 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 401843 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 401915 T2220 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 401916 T2220 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55698
[junit4:junit4] 2> 401917 T2220 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 401917 T2220 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 401918 T2220 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370579066514
[junit4:junit4] 2> 401918 T2220 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370579066514/solr.xml
[junit4:junit4] 2> 401918 T2220 oasc.CoreContainer.<init> New CoreContainer 9407867
[junit4:junit4] 2> 401919 T2220 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370579066514/'
[junit4:junit4] 2> 401919 T2220 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370579066514/'
[junit4:junit4] 2> 401964 T2220 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 401965 T2220 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 401965 T2220 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 401966 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 401966 T2220 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 401967 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 401967 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 401967 T2220 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 401968 T2220 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 401968 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 401971 T2220 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 401972 T2220 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:44049/solr
[junit4:junit4] 2> 401972 T2220 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 401973 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 401974 T2292 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9d8d3f name:ZooKeeperConnection Watcher:127.0.0.1:44049 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 401974 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 401975 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 401978 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 401979 T2294 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b667a8 name:ZooKeeperConnection Watcher:127.0.0.1:44049/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 401980 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 401982 T2220 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 402984 T2220 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55698_
[junit4:junit4] 2> 402985 T2220 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55698_
[junit4:junit4] 2> 402987 T2262 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> 402987 T2278 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> 402988 T2249 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> 402987 T2242 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> 402989 T2294 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 402989 T2278 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 402990 T2262 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 402990 T2249 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 402990 T2242 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 402994 T2295 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370579066514/collection1
[junit4:junit4] 2> 402994 T2295 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 402994 T2295 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 402995 T2295 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 402995 T2295 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370579066514/collection1/'
[junit4:junit4] 2> 402996 T2295 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370579066514/collection1/lib/README' to classloader
[junit4:junit4] 2> 402996 T2295 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370579066514/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 403036 T2295 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 403075 T2295 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 403076 T2295 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 403082 T2295 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 403290 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 403291 T2243 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:35197__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:35197_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35197"}
[junit4:junit4] 2> 403294 T2294 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> 403294 T2242 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> 403294 T2278 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> 403294 T2249 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> 403295 T2262 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> 403387 T2295 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 403389 T2295 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 403390 T2295 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 403394 T2295 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 403414 T2295 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 403414 T2295 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370579066514/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty3/
[junit4:junit4] 2> 403414 T2295 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1debd03
[junit4:junit4] 2> 403415 T2295 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 403415 T2295 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty3
[junit4:junit4] 2> 403415 T2295 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty3/index/
[junit4:junit4] 2> 403416 T2295 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 403416 T2295 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty3/index
[junit4:junit4] 2> 403417 T2295 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a81f3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ca4be),segFN=segments_1,generation=1}
[junit4:junit4] 2> 403418 T2295 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 403419 T2295 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 403420 T2295 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 403420 T2295 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 403421 T2295 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 403421 T2295 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 403421 T2295 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 403422 T2295 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 403422 T2295 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 403422 T2295 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 403425 T2295 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 403427 T2295 oass.SolrIndexSearcher.<init> Opening Searcher@1ed535c main
[junit4:junit4] 2> 403427 T2295 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty3/tlog
[junit4:junit4] 2> 403428 T2295 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 403428 T2295 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 403431 T2296 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ed535c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 403433 T2295 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 403433 T2295 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 404799 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 404800 T2243 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:55698_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55698"}
[junit4:junit4] 2> 404800 T2243 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 404800 T2243 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 404827 T2294 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> 404827 T2278 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> 404827 T2242 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> 404827 T2249 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> 404827 T2262 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> 405434 T2295 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 405435 T2295 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55698 collection:collection1 shard:shard1
[junit4:junit4] 2> 405437 T2295 oasc.ZkController.register We are http://127.0.0.1:55698/collection1/ and leader is http://127.0.0.1:53916/collection1/
[junit4:junit4] 2> 405437 T2295 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55698
[junit4:junit4] 2> 405438 T2295 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 405438 T2295 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C433 name=collection1 org.apache.solr.core.SolrCore@1056abb url=http://127.0.0.1:55698/collection1 node=127.0.0.1:55698_ C433_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:55698_, base_url=http://127.0.0.1:55698}
[junit4:junit4] 2> 405439 T2297 C433 P55698 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 405439 T2295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 405440 T2297 C433 P55698 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 405441 T2297 C433 P55698 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 405441 T2297 C433 P55698 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 405441 T2220 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 405441 T2220 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 405442 T2297 C433 P55698 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 405442 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 405445 T2258 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:55698__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 405522 T2220 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 405524 T2220 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:33202
[junit4:junit4] 2> 405525 T2220 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 405525 T2220 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 405526 T2220 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370579070113
[junit4:junit4] 2> 405526 T2220 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370579070113/solr.xml
[junit4:junit4] 2> 405526 T2220 oasc.CoreContainer.<init> New CoreContainer 10615949
[junit4:junit4] 2> 405527 T2220 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370579070113/'
[junit4:junit4] 2> 405527 T2220 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370579070113/'
[junit4:junit4] 2> 405603 T2220 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 405603 T2220 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 405603 T2220 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 405604 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 405604 T2220 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 405604 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 405605 T2220 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 405605 T2220 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 405606 T2220 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 405606 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 405609 T2220 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 405610 T2220 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:44049/solr
[junit4:junit4] 2> 405610 T2220 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 405611 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 405612 T2309 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c50e8d name:ZooKeeperConnection Watcher:127.0.0.1:44049 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 405612 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 405613 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 405616 T2220 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 405617 T2311 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8184ce name:ZooKeeperConnection Watcher:127.0.0.1:44049/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 405617 T2220 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 405619 T2220 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 406331 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 406332 T2243 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:55698__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:55698_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55698"}
[junit4:junit4] 2> 406335 T2262 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> 406335 T2242 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> 406335 T2311 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> 406335 T2294 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> 406335 T2249 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> 406335 T2278 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> 406446 T2258 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:55698__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 406446 T2258 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:55698__collection1&state=recovering&nodeName=127.0.0.1:55698_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 406622 T2220 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33202_
[junit4:junit4] 2> 406623 T2220 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:33202_
[junit4:junit4] 2> 406625 T2294 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> 406625 T2278 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> 406625 T2242 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> 406626 T2311 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 406626 T2311 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> 406625 T2249 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> 406627 T2294 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 406625 T2262 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> 406628 T2249 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 406628 T2278 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 406628 T2242 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 406629 T2262 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 406632 T2312 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370579070113/collection1
[junit4:junit4] 2> 406632 T2312 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 406633 T2312 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 406633 T2312 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 406634 T2312 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370579070113/collection1/'
[junit4:junit4] 2> 406634 T2312 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370579070113/collection1/lib/README' to classloader
[junit4:junit4] 2> 406635 T2312 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370579070113/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 406663 T2312 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 406697 T2312 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 406698 T2312 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 406703 T2312 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 406887 T1106 oasc.OverseerCollectionProcessor.run WARN Overseer cannot talk to ZK
[junit4:junit4] 2> 406994 T2312 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 406996 T2312 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 406998 T2312 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 407000 T2312 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 407015 T2312 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 407015 T2312 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370579070113/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/
[junit4:junit4] 2> 407015 T2312 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1debd03
[junit4:junit4] 2> 407016 T2312 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 407016 T2312 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4
[junit4:junit4] 2> 407017 T2312 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/index/
[junit4:junit4] 2> 407017 T2312 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 407017 T2312 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/index
[junit4:junit4] 2> 407020 T2312 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1714ecd lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cd8006),segFN=segments_1,generation=1}
[junit4:junit4] 2> 407020 T2312 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 407022 T2312 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 407022 T2312 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 407023 T2312 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 407023 T2312 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 407023 T2312 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 407024 T2312 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 407024 T2312 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 407024 T2312 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 407025 T2312 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 407027 T2312 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 407029 T2312 oass.SolrIndexSearcher.<init> Opening Searcher@98920c main
[junit4:junit4] 2> 407029 T2312 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/tlog
[junit4:junit4] 2> 407030 T2312 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 407030 T2312 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 407034 T2313 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@98920c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 407035 T2312 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 407035 T2312 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 407837 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 407838 T2243 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:33202_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33202"}
[junit4:junit4] 2> 407838 T2243 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 407838 T2243 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 407840 T2262 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> 407840 T2278 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> 407840 T2242 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> 407840 T2294 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> 407840 T2311 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> 407840 T2249 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> 408043 T2312 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 408044 T2312 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:33202 collection:collection1 shard:shard2
[junit4:junit4] 2> 408051 T2312 oasc.ZkController.register We are http://127.0.0.1:33202/collection1/ and leader is http://127.0.0.1:35197/collection1/
[junit4:junit4] 2> 408051 T2312 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:33202
[junit4:junit4] 2> 408052 T2312 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 408052 T2312 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C434 name=collection1 org.apache.solr.core.SolrCore@150c243 url=http://127.0.0.1:33202/collection1 node=127.0.0.1:33202_ C434_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:33202_, base_url=http://127.0.0.1:33202}
[junit4:junit4] 2> 408056 T2314 C434 P33202 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 408058 T2312 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 408058 T2314 C434 P33202 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 408059 T2314 C434 P33202 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 408059 T2314 C434 P33202 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 408060 T2314 C434 P33202 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 408061 T2220 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 408061 T2220 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 408062 T2220 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 408064 T2274 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:33202__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 408070 T2220 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 408072 T2220 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 408073 T2220 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 408074 T2220 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C435 name=collection1 org.apache.solr.core.SolrCore@1056abb url=http://127.0.0.1:55698/collection1 node=127.0.0.1:55698_ C435_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:55698_, base_url=http://127.0.0.1:55698}
[junit4:junit4] 2> 408447 T2297 C435 P55698 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53916/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 408448 T2297 C435 P55698 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55698 START replicas=[http://127.0.0.1:53916/collection1/] nUpdates=100
[junit4:junit4] 2> 408448 T2297 C435 P55698 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 408448 T2297 C435 P55698 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 408448 T2297 C435 P55698 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 408448 T2297 C435 P55698 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 408448 T2297 C435 P55698 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 408449 T2297 C435 P55698 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53916/collection1/. core=collection1
[junit4:junit4] 2> 408449 T2297 C435 P55698 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C436 name=collection1 org.apache.solr.core.SolrCore@167f0f8 url=http://127.0.0.1:53916/collection1 node=127.0.0.1:53916_ C436_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53916_, base_url=http://127.0.0.1:53916, leader=true}
[junit4:junit4] 2> 408454 T2257 C436 P53916 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 408458 T2256 C436 P53916 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 408459 T2256 C436 P53916 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9c25c0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@871745),segFN=segments_1,generation=1}
[junit4:junit4] 2> 408460 T2256 C436 P53916 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 408461 T2256 C436 P53916 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9c25c0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@871745),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9c25c0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@871745),segFN=segments_2,generation=2}
[junit4:junit4] 2> 408461 T2256 C436 P53916 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 408462 T2256 C436 P53916 oass.SolrIndexSearcher.<init> Opening Searcher@18b31ca realtime
[junit4:junit4] 2> 408462 T2256 C436 P53916 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 408462 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 408463 T2297 C435 P55698 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 408463 T2297 C435 P55698 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 408465 T2256 C436 P53916 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 408465 T2256 C436 P53916 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 408466 T2297 C435 P55698 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 408466 T2297 C435 P55698 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 408467 T2297 C435 P55698 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 408468 T2258 C436 P53916 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 408469 T2297 C435 P55698 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 408470 T2297 C435 P55698 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty3/index.20130607022433137
[junit4:junit4] 2> 408470 T2297 C435 P55698 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@455cba lockFactory=org.apache.lucene.store.NativeFSLockFactory@ee0740) fullCopy=false
[junit4:junit4] 2> 408472 T2255 C436 P53916 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 408473 T2297 C435 P55698 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 408474 T2297 C435 P55698 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 408474 T2297 C435 P55698 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 408475 T2297 C435 P55698 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a81f3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ca4be),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a81f3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ca4be),segFN=segments_2,generation=2}
[junit4:junit4] 2> 408475 T2297 C435 P55698 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 408475 T2297 C435 P55698 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 408476 T2297 C435 P55698 oass.SolrIndexSearcher.<init> Opening Searcher@1238448 main
[junit4:junit4] 2> 408476 T2296 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1238448 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 408477 T2297 C435 P55698 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty3/index.20130607022433137 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty3/index.20130607022433137;done=true>>]
[junit4:junit4] 2> 408477 T2297 C435 P55698 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty3/index.20130607022433137
[junit4:junit4] 2> 408477 T2297 C435 P55698 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty3/index.20130607022433137
[junit4:junit4] 2> 408478 T2297 C435 P55698 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 408478 T2297 C435 P55698 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 408478 T2297 C435 P55698 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 408478 T2297 C435 P55698 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 408491 T2297 C435 P55698 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 409075 T2220 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 409343 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 409344 T2243 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:33202__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:33202_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33202"}
[junit4:junit4] 2> 409347 T2243 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:55698__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:55698_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55698"}
[junit4:junit4] 2> 409350 T2262 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> 409350 T2294 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> 409350 T2242 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> 409350 T2311 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> 409350 T2249 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> 409350 T2278 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> 410064 T2274 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:33202__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 410065 T2274 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:33202__collection1&state=recovering&nodeName=127.0.0.1:33202_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2001
[junit4:junit4] 2> 410077 T2220 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 411078 T2220 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 411511 T1114 oasc.OverseerCollectionProcessor.run WARN Overseer cannot talk to ZK
[junit4:junit4] 2> C434_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:33202_, base_url=http://127.0.0.1:33202}
[junit4:junit4] 2> 412066 T2314 C434 P33202 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:35197/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 412066 T2314 C434 P33202 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:33202 START replicas=[http://127.0.0.1:35197/collection1/] nUpdates=100
[junit4:junit4] 2> 412066 T2314 C434 P33202 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 412067 T2314 C434 P33202 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 412067 T2314 C434 P33202 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 412067 T2314 C434 P33202 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 412067 T2314 C434 P33202 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 412067 T2314 C434 P33202 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:35197/collection1/. core=collection1
[junit4:junit4] 2> 412067 T2314 C434 P33202 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C437 name=collection1 org.apache.solr.core.SolrCore@17eb1ec url=http://127.0.0.1:35197/collection1 node=127.0.0.1:35197_ C437_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:35197_, base_url=http://127.0.0.1:35197, leader=true}
[junit4:junit4] 2> 412073 T2272 C437 P35197 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 412076 T2274 C437 P35197 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 412078 T2274 C437 P35197 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@130c5b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f95c77),segFN=segments_1,generation=1}
[junit4:junit4] 2> 412078 T2274 C437 P35197 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 412079 T2274 C437 P35197 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@130c5b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f95c77),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@130c5b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f95c77),segFN=segments_2,generation=2}
[junit4:junit4] 2> 412079 T2274 C437 P35197 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 412080 T2220 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 412080 T2274 C437 P35197 oass.SolrIndexSearcher.<init> Opening Searcher@16e4e59 realtime
[junit4:junit4] 2> 412081 T2274 C437 P35197 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 412082 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 412083 T2314 C434 P33202 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 412083 T2314 C434 P33202 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 412084 T2271 C437 P35197 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 412085 T2271 C437 P35197 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 412085 T2314 C434 P33202 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 412086 T2314 C434 P33202 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 412086 T2314 C434 P33202 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 412088 T2272 C437 P35197 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 412088 T2314 C434 P33202 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 412089 T2314 C434 P33202 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/index.20130607022436757
[junit4:junit4] 2> 412089 T2314 C434 P33202 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@c88966 lockFactory=org.apache.lucene.store.NativeFSLockFactory@135d780) fullCopy=false
[junit4:junit4] 2> 412092 T2274 C437 P35197 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 412093 T2314 C434 P33202 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 412093 T2314 C434 P33202 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 412094 T2314 C434 P33202 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 412095 T2314 C434 P33202 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1714ecd lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cd8006),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1714ecd lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cd8006),segFN=segments_2,generation=2}
[junit4:junit4] 2> 412095 T2314 C434 P33202 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 412095 T2314 C434 P33202 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 412095 T2314 C434 P33202 oass.SolrIndexSearcher.<init> Opening Searcher@5eadd0 main
[junit4:junit4] 2> 412096 T2313 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5eadd0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 412097 T2314 C434 P33202 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/index.20130607022436757 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/index.20130607022436757;done=true>>]
[junit4:junit4] 2> 412097 T2314 C434 P33202 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/index.20130607022436757
[junit4:junit4] 2> 412097 T2314 C434 P33202 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/index.20130607022436757
[junit4:junit4] 2> 412098 T2314 C434 P33202 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 412098 T2314 C434 P33202 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 412098 T2314 C434 P33202 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 412098 T2314 C434 P33202 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 412099 T2314 C434 P33202 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 412924 T2243 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 412925 T2243 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:33202__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:33202_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33202"}
[junit4:junit4] 2> 412928 T2249 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> 412928 T2242 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> 412928 T2311 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> 412928 T2262 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> 412928 T2294 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> 412928 T2278 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> 413082 T2220 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 413083 T2220 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C438 name=collection1 org.apache.solr.core.SolrCore@1aef7f0 url=http://127.0.0.1:40438/collection1 node=127.0.0.1:40438_ C438_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:40438_, base_url=http://127.0.0.1:40438, leader=true}
[junit4:junit4] 2> 413090 T2237 C438 P40438 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 413091 T2237 C438 P40438 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c88bab lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b54b47),segFN=segments_1,generation=1}
[junit4:junit4] 2> 413092 T2237 C438 P40438 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 413093 T2237 C438 P40438 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c88bab lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b54b47),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c88bab lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b54b47),segFN=segments_2,generation=2}
[junit4:junit4] 2> 413093 T2237 C438 P40438 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 413094 T2237 C438 P40438 oass.SolrIndexSearcher.<init> Opening Searcher@c887bf main
[junit4:junit4] 2> 413094 T2237 C438 P40438 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 413095 T2246 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c887bf main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 413095 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 413099 T2255 C436 P53916 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 413099 T2255 C436 P53916 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9c25c0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@871745),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9c25c0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@871745),segFN=segments_3,generation=3}
[junit4:junit4] 2> 413100 T2255 C436 P53916 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 413100 T2255 C436 P53916 oass.SolrIndexSearcher.<init> Opening Searcher@f5cccb main
[junit4:junit4] 2> 413101 T2255 C436 P53916 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 413101 T2264 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f5cccb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 413102 T2255 C436 P53916 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:55698/collection1/, StdNode: http://127.0.0.1:35197/collection1/, StdNode: http://127.0.0.1:33202/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 413104 T2273 C437 P35197 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 413105 T2273 C437 P35197 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@130c5b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f95c77),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@130c5b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f95c77),segFN=segments_3,generation=3}
[junit4:junit4] 2> 413105 T2273 C437 P35197 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 413106 T2273 C437 P35197 oass.SolrIndexSearcher.<init> Opening Searcher@e42961 main
[junit4:junit4] 2> 413106 T2273 C437 P35197 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 413107 T2280 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e42961 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 413107 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 2> C434_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:33202_, base_url=http://127.0.0.1:33202}
[junit4:junit4] 2> 413107 T2305 C434 P33202 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C435_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55698_, base_url=http://127.0.0.1:55698}
[junit4:junit4] 2> 413107 T2288 C435 P55698 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 413108 T2305 C434 P33202 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1714ecd lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cd8006),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1714ecd lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cd8006),segFN=segments_3,generation=3}
[junit4:junit4] 2> 413108 T2288 C435 P55698 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a81f3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ca4be),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a81f3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ca4be),segFN=segments_3,generation=3}
[junit4:junit4] 2> 413109 T2288 C435 P55698 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 413108 T2305 C434 P33202 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 413110 T2288 C435 P55698 oass.SolrIndexSearcher.<init> Opening Searcher@53ec4d main
[junit4:junit4] 2> 413110 T2305 C434 P33202 oass.SolrIndexSearcher.<init> Opening Searcher@594762 main
[junit4:junit4] 2> 413111 T2288 C435 P55698 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 413111 T2296 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@53ec4d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 413111 T2305 C434 P33202 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 413112 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 413112 T2313 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@594762 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 413112 T2305 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 413113 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> 413114 T2220 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 413116 T2257 C436 P53916 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 413117 T2289 C435 P55698 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 413119 T2271 C437 P35197 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 413121 T2304 C434 P33202 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 414728 T1124 oasc.OverseerCollectionProcessor.run WARN Overseer cannot talk to ZK
[junit4:junit4] 2> 415125 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437156329173024768)} 0 1
[junit4:junit4] 2> 415130 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1437156329175121920&update.from=http://127.0.0.1:53916/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437156329175121920)} 0 1
[junit4:junit4] 2> 415133 T2304 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1437156329178267648&update.from=http://127.0.0.1:35197/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437156329178267648)} 0 1
[junit4:junit4] 2> 415134 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1437156329178267648)} 0 4
[junit4:junit4] 2> 415134 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437156329175121920)} 0 7
[junit4:junit4] 2> 415137 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1437156329185607680)]} 0 1
[junit4:junit4] 2> 415142 T2289 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1437156329187704832)]} 0 1
[junit4:junit4] 2> 415142 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1437156329187704832)]} 0 3
[junit4:junit4] 2> 415143 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 5
[junit4:junit4] 2> 415145 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1437156329193996288)]} 0 0
[junit4:junit4] 2> 415149 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1437156329196093440)]} 0 0
[junit4:junit4] 2> 415150 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1437156329196093440)]} 0 3
[junit4:junit4] 2> 415152 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1437156329200287744)]} 0 1
[junit4:junit4] 2> 415156 T2305 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1437156329203433472)]} 0 1
[junit4:junit4] 2> 415156 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1437156329203433472)]} 0 3
[junit4:junit4] 2> 415158 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1437156329207627776)]} 0 0
[junit4:junit4] 2> 415162 T2306 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1437156329209724928)]} 0 0
[junit4:junit4] 2> 415163 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1437156329209724928)]} 0 3
[junit4:junit4] 2> 415165 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1437156329214967808)]} 0 1
[junit4:junit4] 2> 415171 T2287 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1437156329219162112)]} 0 0
[junit4:junit4] 2> 415172 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1437156329219162112)]} 0 4
[junit4:junit4] 2> 415173 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4]} 0 6
[junit4:junit4] 2> 415175 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1437156329225453568)]} 0 0
[junit4:junit4] 2> 415181 T2307 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1437156329229647872)]} 0 1
[junit4:junit4] 2> 415181 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1437156329229647872)]} 0 3
[junit4:junit4] 2> 415182 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5]} 0 5
[junit4:junit4] 2> 415184 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1437156329234890752)]} 0 1
[junit4:junit4] 2> 415189 T2304 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1437156329238036480)]} 0 0
[junit4:junit4] 2> 415190 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[6 (1437156329238036480)]} 0 3
[junit4:junit4] 2> 415190 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6]} 0 4
[junit4:junit4] 2> 415192 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1437156329243279360)]} 0 0
[junit4:junit4] 2> 415197 T2305 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1437156329246425088)]} 0 0
[junit4:junit4] 2> 415198 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1437156329246425088)]} 0 3
[junit4:junit4] 2> 415198 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7]} 0 4
[junit4:junit4] 2> 415200 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1437156329251667968)]} 0 0
[junit4:junit4] 2> 415204 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1437156329253765120)]} 0 0
[junit4:junit4] 2> 415205 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1437156329253765120)]} 0 3
[junit4:junit4] 2> 415207 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1437156329259008000)]} 0 1
[junit4:junit4] 2> 415210 T2306 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1437156329261105152)]} 0 0
[junit4:junit4] 2> 415211 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1437156329261105152)]} 0 3
[junit4:junit4] 2> 415213 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1437156329265299456)]} 0 0
[junit4:junit4] 2> 415219 T2289 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1437156329269493760)]} 0 1
[junit4:junit4] 2> 415219 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1437156329269493760)]} 0 3
[junit4:junit4] 2> 415220 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10]} 0 5
[junit4:junit4] 2> 415222 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1437156329274736640)]} 0 1
[junit4:junit4] 2> 415226 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1437156329276833792)]} 0 0
[junit4:junit4] 2> 415227 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1437156329276833792)]} 0 3
[junit4:junit4] 2> 415230 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1437156329283125248)]} 0 1
[junit4:junit4] 2> 415236 T2287 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1437156329287319552)]} 0 0
[junit4:junit4] 2> 415237 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1437156329287319552)]} 0 3
[junit4:junit4] 2> 415238 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12]} 0 6
[junit4:junit4] 2> 415240 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1437156329293611008)]} 0 0
[junit4:junit4] 2> 415245 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1437156329296756736)]} 0 0
[junit4:junit4] 2> 415246 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1437156329296756736)]} 0 3
[junit4:junit4] 2> 415248 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1437156329301999616)]} 0 0
[junit4:junit4] 2> 415252 T2289 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1437156329304096768)]} 0 0
[junit4:junit4] 2> 415253 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1437156329304096768)]} 0 3
[junit4:junit4] 2> 415255 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1437156329309339648)]} 0 0
[junit4:junit4] 2> 415261 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1437156329313533952)]} 0 0
[junit4:junit4] 2> 415262 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1437156329313533952)]} 0 3
[junit4:junit4] 2> 415262 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15]} 0 4
[junit4:junit4] 2> 415264 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1437156329318776832)]} 0 0
[junit4:junit4] 2> 415270 T2287 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1437156329322971136)]} 0 1
[junit4:junit4] 2> 415270 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1437156329322971136)]} 0 2
[junit4:junit4] 2> 415270 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16]} 0 4
[junit4:junit4] 2> 415273 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1437156329327165440)]} 0 1
[junit4:junit4] 2> 415278 T2307 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1437156329331359744)]} 0 0
[junit4:junit4] 2> 415279 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[17 (1437156329331359744)]} 0 3
[junit4:junit4] 2> 415279 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17]} 0 4
[junit4:junit4] 2> 415282 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1437156329336602624)]} 0 1
[junit4:junit4] 2> 415286 T2304 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1437156329339748352)]} 0 1
[junit4:junit4] 2> 415286 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1437156329339748352)]} 0 3
[junit4:junit4] 2> 415289 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1437156329344991232)]} 0 1
[junit4:junit4] 2> 415293 T2305 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1437156329347088384)]} 0 0
[junit4:junit4] 2> 415294 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1437156329347088384)]} 0 3
[junit4:junit4] 2> 415296 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1437156329352331264)]} 0 0
[junit4:junit4] 2> 415301 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1437156329355476992)]} 0 0
[junit4:junit4] 2> 415302 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[20 (1437156329355476992)]} 0 3
[junit4:junit4] 2> 415302 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20]} 0 4
[junit4:junit4] 2> 415304 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1437156329360719872)]} 0 0
[junit4:junit4] 2> 415309 T2306 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1437156329363865600)]} 0 0
[junit4:junit4] 2> 415310 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1437156329363865600)]} 0 4
[junit4:junit4] 2> 415313 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1437156329370157056)]} 0 0
[junit4:junit4] 2> 415319 T2289 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1437156329373302784)]} 0 0
[junit4:junit4] 2> 415320 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1437156329373302784)]} 0 4
[junit4:junit4] 2> 415323 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1437156329380642816)]} 0 0
[junit4:junit4] 2> 415329 T2307 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1437156329383788544)]} 0 1
[junit4:junit4] 2> 415330 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1437156329383788544)]} 0 4
[junit4:junit4] 2> 415334 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1437156329391128576)]} 0 1
[junit4:junit4] 2> 415342 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1437156329397420032)]} 0 1
[junit4:junit4] 2> 415343 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[24 (1437156329397420032)]} 0 4
[junit4:junit4] 2> 415344 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24]} 0 7
[junit4:junit4] 2> 415347 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1437156329405808640)]} 0 1
[junit4:junit4] 2> 415353 T2304 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1437156329408954368)]} 0 1
[junit4:junit4] 2> 415354 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1437156329408954368)]} 0 4
[junit4:junit4] 2> 415358 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1437156329417342976)]} 0 1
[junit4:junit4] 2> 415364 T2305 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1437156329421537280)]} 0 0
[junit4:junit4] 2> 415365 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[26 (1437156329421537280)]} 0 3
[junit4:junit4] 2> 415365 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26]} 0 4
[junit4:junit4] 2> 415367 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1437156329426780160)]} 0 0
[junit4:junit4] 2> 415371 T2287 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1437156329428877312)]} 0 0
[junit4:junit4] 2> 415371 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1437156329428877312)]} 0 2
[junit4:junit4] 2> 415373 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1437156329433071616)]} 0 0
[junit4:junit4] 2> 415377 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1437156329435168768)]} 0 0
[junit4:junit4] 2> 415378 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1437156329435168768)]} 0 3
[junit4:junit4] 2> 415380 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1437156329440411648)]} 0 0
[junit4:junit4] 2> 415384 T2306 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1437156329442508800)]} 0 1
[junit4:junit4] 2> 415384 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1437156329442508800)]} 0 2
[junit4:junit4] 2> 415386 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1437156329446703104)]} 0 0
[junit4:junit4] 2> 415392 T2307 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1437156329450897408)]} 0 0
[junit4:junit4] 2> 415392 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1437156329450897408)]} 0 2
[junit4:junit4] 2> 415393 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30]} 0 5
[junit4:junit4] 2> 415395 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1437156329456140288)]} 0 0
[junit4:junit4] 2> 415399 T2304 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1437156329458237440)]} 0 0
[junit4:junit4] 2> 415400 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1437156329458237440)]} 0 3
[junit4:junit4] 2> 415402 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1437156329463480320)]} 0 0
[junit4:junit4] 2> 415408 T2289 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1437156329467674624)]} 0 0
[junit4:junit4] 2> 415408 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[32 (1437156329467674624)]} 0 2
[junit4:junit4] 2> 415409 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32]} 0 5
[junit4:junit4] 2> 415411 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1437156329472917504)]} 0 0
[junit4:junit4] 2> 415415 T2305 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1437156329475014656)]} 0 1
[junit4:junit4] 2> 415415 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1437156329475014656)]} 0 2
[junit4:junit4] 2> 415417 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1437156329479208960)]} 0 0
[junit4:junit4] 2> 415421 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1437156329481306112)]} 0 0
[junit4:junit4] 2> 415422 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1437156329481306112)]} 0 3
[junit4:junit4] 2> 415424 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1437156329486548992)]} 0 0
[junit4:junit4] 2> 415430 T2287 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1437156329490743296)]} 0 1
[junit4:junit4] 2> 415430 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[35 (1437156329490743296)]} 0 2
[junit4:junit4] 2> 415431 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35]} 0 5
[junit4:junit4] 2> 415433 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1437156329495986176)]} 0 0
[junit4:junit4] 2> 415438 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1437156329498083328)]} 0 1
[junit4:junit4] 2> 415438 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1437156329498083328)]} 0 3
[junit4:junit4] 2> 415441 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1437156329504374784)]} 0 0
[junit4:junit4] 2> 415445 T2306 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1437156329506471936)]} 0 0
[junit4:junit4] 2> 415446 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1437156329506471936)]} 0 3
[junit4:junit4] 2> 415448 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1437156329510666240)]} 0 1
[junit4:junit4] 2> 415452 T2289 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1437156329513811968)]} 0 1
[junit4:junit4] 2> 415452 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1437156329513811968)]} 0 2
[junit4:junit4] 2> 415454 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1437156329518006272)]} 0 0
[junit4:junit4] 2> 415460 T2307 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1437156329522200576)]} 0 1
[junit4:junit4] 2> 415460 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[39 (1437156329522200576)]} 0 2
[junit4:junit4] 2> 415461 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39]} 0 5
[junit4:junit4] 2> 415463 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1437156329527443456)]} 0 1
[junit4:junit4] 2> 415466 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1437156329529540608)]} 0 0
[junit4:junit4] 2> 415467 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1437156329529540608)]} 0 2
[junit4:junit4] 2> 415469 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1437156329533734912)]} 0 0
[junit4:junit4] 2> 415474 T2287 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1437156329537929216)]} 0 0
[junit4:junit4] 2> 415475 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[41 (1437156329537929216)]} 0 3
[junit4:junit4] 2> 415475 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41]} 0 4
[junit4:junit4] 2> 415478 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1437156329542123520)]} 0 1
[junit4:junit4] 2> 415482 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1437156329545269248)]} 0 1
[junit4:junit4] 2> 415482 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1437156329545269248)]} 0 2
[junit4:junit4] 2> 415485 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1437156329550512128)]} 0 1
[junit4:junit4] 2> 415490 T2289 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1437156329553657856)]} 0 0
[junit4:junit4] 2> 415491 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[43 (1437156329553657856)]} 0 3
[junit4:junit4] 2> 415491 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43]} 0 4
[junit4:junit4] 2> 415493 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1437156329558900736)]} 0 0
[junit4:junit4] 2> 415499 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1437156329563095040)]} 0 0
[junit4:junit4] 2> 415500 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[44 (1437156329563095040)]} 0 3
[junit4:junit4] 2> 415501 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44]} 0 6
[junit4:junit4] 2> 415503 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1437156329569386496)]} 0 0
[junit4:junit4] 2> 415507 T2304 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1437156329571483648)]} 0 0
[junit4:junit4] 2> 415507 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1437156329571483648)]} 0 2
[junit4:junit4] 2> 415510 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1437156329576726528)]} 0 0
[junit4:junit4] 2> 415516 T2287 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1437156329580920832)]} 0 1
[junit4:junit4] 2> 415517 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[46 (1437156329580920832)]} 0 3
[junit4:junit4] 2> 415517 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46]} 0 5
[junit4:junit4] 2> 415519 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1437156329586163712)]} 0 0
[junit4:junit4] 2> 415523 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1437156329588260864)]} 0 0
[junit4:junit4] 2> 415524 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1437156329588260864)]} 0 3
[junit4:junit4] 2> 415526 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1437156329592455168)]} 0 1
[junit4:junit4] 2> 415529 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1437156329595600896)]} 0 0
[junit4:junit4] 2> 415530 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1437156329595600896)]} 0 3
[junit4:junit4] 2> 415532 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1437156329599795200)]} 0 0
[junit4:junit4] 2> 415536 T2287 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1437156329601892352)]} 0 0
[junit4:junit4] 2> 415537 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1437156329601892352)]} 0 3
[junit4:junit4] 2> 415539 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1437156329607135232)]} 0 1
[junit4:junit4] 2> 415545 T2289 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1437156329610280960)]} 0 1
[junit4:junit4] 2> 415546 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1437156329610280960)]} 0 5
[junit4:junit4] 2> 415549 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1437156329616572416)]} 0 1
[junit4:junit4] 2> 415554 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1437156329619718144)]} 0 1
[junit4:junit4] 2> 415555 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1437156329619718144)]} 0 4
[junit4:junit4] 2> 415558 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1437156329626009600)]} 0 1
[junit4:junit4] 2> 415563 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1437156329630203904)]} 0 1
[junit4:junit4] 2> 415563 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1437156329630203904)]} 0 3
[junit4:junit4] 2> 415566 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1437156329635446784)]} 0 1
[junit4:junit4] 2> 415574 T2306 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1437156329640689664)]} 0 0
[junit4:junit4] 2> 415575 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1437156329640689664)]} 0 4
[junit4:junit4] 2> 415576 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53]} 0 7
[junit4:junit4] 2> 415580 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1437156329649078272)]} 0 1
[junit4:junit4] 2> 415586 T2287 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1437156329654321152)]} 0 1
[junit4:junit4] 2> 415586 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[54 (1437156329654321152)]} 0 2
[junit4:junit4] 2> 415587 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54]} 0 5
[junit4:junit4] 2> 415589 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1437156329659564032)]} 0 1
[junit4:junit4] 2> 415593 T2289 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1437156329661661184)]} 0 1
[junit4:junit4] 2> 415593 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1437156329661661184)]} 0 2
[junit4:junit4] 2> 415595 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1437156329665855488)]} 0 0
[junit4:junit4] 2> 415601 T2304 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1437156329670049792)]} 0 0
[junit4:junit4] 2> 415601 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[56 (1437156329670049792)]} 0 2
[junit4:junit4] 2> 415602 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56]} 0 5
[junit4:junit4] 2> 415604 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1437156329675292672)]} 0 0
[junit4:junit4] 2> 415608 T2305 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1437156329677389824)]} 0 0
[junit4:junit4] 2> 415608 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1437156329677389824)]} 0 2
[junit4:junit4] 2> 415610 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1437156329681584128)]} 0 0
[junit4:junit4] 2> 415614 T2307 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1437156329683681280)]} 0 0
[junit4:junit4] 2> 415615 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1437156329683681280)]} 0 3
[junit4:junit4] 2> 415617 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1437156329688924160)]} 0 0
[junit4:junit4] 2> 415621 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1437156329691021312)]} 0 0
[junit4:junit4] 2> 415622 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1437156329691021312)]} 0 3
[junit4:junit4] 2> 415624 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1437156329695215616)]} 0 1
[junit4:junit4] 2> 415629 T2306 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1437156329699409920)]} 0 0
[junit4:junit4] 2> 415630 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[60 (1437156329699409920)]} 0 3
[junit4:junit4] 2> 415630 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60]} 0 5
[junit4:junit4] 2> 415632 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1437156329704652800)]} 0 0
[junit4:junit4] 2> 415638 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1437156329708847104)]} 0 0
[junit4:junit4] 2> 415639 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[61 (1437156329708847104)]} 0 3
[junit4:junit4] 2> 415639 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61]} 0 5
[junit4:junit4] 2> 415641 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1437156329714089984)]} 0 0
[junit4:junit4] 2> 415646 T2304 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1437156329717235712)]} 0 1
[junit4:junit4] 2> 415646 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1437156329717235712)]} 0 3
[junit4:junit4] 2> 415648 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1437156329721430016)]} 0 0
[junit4:junit4] 2> 415654 T2287 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1437156329725624320)]} 0 0
[junit4:junit4] 2> 415654 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[63 (1437156329725624320)]} 0 2
[junit4:junit4] 2> 415655 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63]} 0 5
[junit4:junit4] 2> 415657 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1437156329730867200)]} 0 1
[junit4:junit4] 2> 415662 T2289 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1437156329734012928)]} 0 0
[junit4:junit4] 2> 415663 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[64 (1437156329734012928)]} 0 3
[junit4:junit4] 2> 415663 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64]} 0 4
[junit4:junit4] 2> 415666 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1437156329739255808)]} 0 1
[junit4:junit4] 2> 415671 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1437156329743450112)]} 0 0
[junit4:junit4] 2> 415672 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[65 (1437156329743450112)]} 0 3
[junit4:junit4] 2> 415672 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65]} 0 5
[junit4:junit4] 2> 415675 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1437156329748692992)]} 0 1
[junit4:junit4] 2> 415679 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1437156329751838720)]} 0 1
[junit4:junit4] 2> 415679 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1437156329751838720)]} 0 3
[junit4:junit4] 2> 415681 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1437156329756033024)]} 0 0
[junit4:junit4] 2> 415685 T2305 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1437156329758130176)]} 0 0
[junit4:junit4] 2> 415686 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1437156329758130176)]} 0 3
[junit4:junit4] 2> 415688 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1437156329763373056)]} 0 1
[junit4:junit4] 2> 415692 T2307 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[68 (1437156329765470208)]} 0 1
[junit4:junit4] 2> 415692 T2271 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1437156329765470208)]} 0 2
[junit4:junit4] 2> 415695 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1437156329769664512)]} 0 1
[junit4:junit4] 2> 415701 T2306 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[69 (1437156329774907392)]} 0 1
[junit4:junit4] 2> 415701 T2272 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[69 (1437156329774907392)]} 0 2
[junit4:junit4] 2> 415702 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69]} 0 5
[junit4:junit4] 2> 415704 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1437156329780150272)]} 0 0
[junit4:junit4] 2> 415708 T2287 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[70 (1437156329782247424)]} 0 1
[junit4:junit4] 2> 415708 T2258 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1437156329782247424)]} 0 2
[junit4:junit4] 2> 415710 T2236 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71 (1437156329786441728)]} 0 0
[junit4:junit4] 2> 415716 T2304 C434 P33202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[71 (1437156329790636032)]} 0 0
[junit4:junit4] 2> 415717 T2273 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[71 (1437156329790636032)]} 0 3
[junit4:junit4] 2> 415717 T2255 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71]} 0 5
[junit4:junit4] 2> 415719 T2235 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1437156329795878912)]} 0 0
[junit4:junit4] 2> 415723 T2289 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[72 (1437156329797976064)]} 0 0
[junit4:junit4] 2> 415724 T2257 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1437156329797976064)]} 0 3
[junit4:junit4] 2> 415726 T2237 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[73 (1437156329802170368)]} 0 1
[junit4:junit4] 2> 415731 T2290 C435 P55698 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53916/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[73 (1437156329806364672)]} 0 0
[junit4:junit4] 2> 415731 T2256 C436 P53916 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:35197/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[73 (1437156329806364672)]} 0 2
[junit4:junit4] 2> 415732 T2274 C437 P35197 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[73]} 0 5
[junit4:junit4] 2> 415734 T2238 C438 P40438 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[74 (1437156329811607552)]} 0 0
[junit4:junit4] 2> 415740 T2288 C435 P55698 oasup.LogUpdateProcessor.finish [collec
[...truncated too long message...]
75 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:55698__collection1_shard1_1_replica1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1_1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":null,
[junit4:junit4] 2> "core":"collection1_shard1_1_replica1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55698_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55698"}
[junit4:junit4] 2> 587054 T2375 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:55698__collection1_shard1_0_replica1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1_0",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":null,
[junit4:junit4] 2> "core":"collection1_shard1_0_replica1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55698_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55698"}
[junit4:junit4] 2> 587057 T2311 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> 587073 T2220 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 587125 T2220 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 33202
[junit4:junit4] 2> 587125 T2220 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=10615949
[junit4:junit4] 2> 588127 T2220 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 588127 T2220 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 588129 T2220 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@150c243
[junit4:junit4] 2> 588130 T2220 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=4,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=784,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 588131 T2220 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 588132 T2220 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 588132 T2220 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 588134 T2220 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 588135 T2220 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 588135 T2220 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4;done=false>>]
[junit4:junit4] 2> 588136 T2220 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4
[junit4:junit4] 2> 588136 T2220 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/index;done=false>>]
[junit4:junit4] 2> 588137 T2220 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955/jetty4/index
[junit4:junit4] 2> 588137 T2375 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89822268880125964-127.0.0.1:33202_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 588160 T2220 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 588215 T2220 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 588217 T2220 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:44049 44049
[junit4:junit4] 2> 588218 T2220 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 40438
[junit4:junit4] 2> !!!! WARNING: best effort to remove /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370579053955 FAILED !!!!!
[junit4:junit4] 2> 588218 T2220 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 588219 T2220 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:44049 44049
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeyShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=6FE8A790C080EF44 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=uk_UA -Dtests.timezone=Etc/GMT+2 -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR 199s J0 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:53916 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([6FE8A790C080EF44:EE0E2988B7DF8F78]: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.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 588231 T2220 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 198954 T2219 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 589439 T2311 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 589440 T2311 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> 589440 T2311 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=Lucene41(blocksize=128), _version_=PostingsFormat(name=Direct), n_ti=PostingsFormat(name=Direct)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=uk_UA, timezone=Etc/GMT+2
[junit4:junit4] 2> NOTE: Linux 3.2.0-45-generic i386/Oracle Corporation 1.7.0_21 (32-bit)/cpus=8,threads=2,free=321037176,total=494927872
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestLMDirichletSimilarityFactory, PrimUtilsTest, AnalysisAfterCoreReloadTest, TestStressVersions, DistributedSpellCheckComponentTest, SliceStateTest, TestLFUCache, StatelessScriptUpdateProcessorFactoryTest, QueryResultKeyTest, TestFaceting, TestUniqueKeyFieldResource, FastVectorHighlighterTest, DistributedTermsComponentTest, TestReplicationHandler, TestIBSimilarityFactory, LukeRequestHandlerTest, DocumentBuilderTest, IndexSchemaTest, OverseerTest, TestStressRecovery, TestLRUCache, SpatialFilterTest, SyncSliceTest, ResponseLogComponentTest, DirectSolrConnectionTest, SolrInfoMBeanTest, BadComponentTest, TestMaxScoreQueryParser, TestDocumentBuilder, TestQuerySenderListener, TestCharFilters, PolyFieldTest, DirectUpdateHandlerOptimizeTest, SpellingQueryConverterTest, TestTrie, MBeansHandlerTest, TermsComponentTest, TestPerFieldSimilarity, TestFastLRUCache, ZkControllerTest, TestReloadAndDeleteDocs, MoreLikeThisHandlerTest, SOLR749Test, DistributedQueryElevationComponentTest, LegacyHTMLStripCharFilterTest, UnloadDistributedZkTest, SolrTestCaseJ4Test, FieldMutatingUpdateProcessorTest, LoggingHandlerTest, ScriptEngineTest, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J0 in 200.25s, 1 test, 1 error <<< FAILURES!
[...truncated 543 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:366: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:887: There were test failures: 297 suites, 1246 tests, 1 error, 13 ignored (7 assumptions)
Total time: 42 minutes 2 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -server -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure