You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/05/20 06:07:49 UTC
[JENKINS] Lucene-Solr-trunk-Linux (64bit/jdk1.8.0-ea-b89) - Build #
5741 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/5741/
Java: 64bit/jdk1.8.0-ea-b89 -XX:+UseCompressedOops -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
shard2 is not consistent. Got 49 from http://127.0.0.1:41567/collection1lastClient and got 48 from http://127.0.0.1:34281/collection1
Stack Trace:
java.lang.AssertionError: shard2 is not consistent. Got 49 from http://127.0.0.1:41567/collection1lastClient and got 48 from http://127.0.0.1:34281/collection1
at __randomizedtesting.SeedInfo.seed([C25C22A2231AB3E4:43BAACBA5445D3D8]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:110)
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:491)
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:724)
Build Log:
[...truncated 10102 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 873516 T2855 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 873519 T2855 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeyShardSplitTest-1369022705148
[junit4:junit4] 2> 873520 T2855 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 873520 T2856 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 873620 T2855 oasc.ZkTestServer.run start zk server on port:43106
[junit4:junit4] 2> 873621 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 873625 T2862 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1fb84cf5 name:ZooKeeperConnection Watcher:127.0.0.1:43106 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 873625 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 873625 T2855 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 873631 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 873633 T2864 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@117fb172 name:ZooKeeperConnection Watcher:127.0.0.1:43106/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 873633 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 873633 T2855 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 873635 T2855 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 873637 T2855 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 873638 T2855 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 873640 T2855 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 873641 T2855 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 873645 T2855 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 873646 T2855 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 873648 T2855 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 873648 T2855 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 873650 T2855 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 873650 T2855 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 873652 T2855 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 873652 T2855 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 873654 T2855 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 873655 T2855 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 873656 T2855 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 873657 T2855 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 873658 T2855 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 873659 T2855 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 873660 T2855 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 873661 T2855 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 873762 T2855 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 873765 T2855 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:34325
[junit4:junit4] 2> 873766 T2855 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 873766 T2855 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 873766 T2855 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369022705299
[junit4:junit4] 2> 873766 T2855 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369022705299/solr.xml
[junit4:junit4] 2> 873767 T2855 oasc.CoreContainer.<init> New CoreContainer 972474945
[junit4:junit4] 2> 873767 T2855 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369022705299/'
[junit4:junit4] 2> 873767 T2855 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369022705299/'
[junit4:junit4] 2> 873809 T2855 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 873809 T2855 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 873809 T2855 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 873810 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 873810 T2855 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 873810 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 873810 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 873811 T2855 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 873811 T2855 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 873811 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 873814 T2855 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 873814 T2855 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43106/solr
[junit4:junit4] 2> 873815 T2855 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 873815 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 873817 T2875 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7fb148d8 name:ZooKeeperConnection Watcher:127.0.0.1:43106 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 873818 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 873819 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 873822 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 873823 T2877 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@472306d8 name:ZooKeeperConnection Watcher:127.0.0.1:43106/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 873824 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 873825 T2855 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 873827 T2855 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 873829 T2855 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 873831 T2855 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34325_
[junit4:junit4] 2> 873831 T2855 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34325_
[junit4:junit4] 2> 873833 T2855 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 873843 T2855 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 873845 T2855 oasc.Overseer.start Overseer (id=89720272004710403-127.0.0.1:34325_-n_0000000000) starting
[junit4:junit4] 2> 873847 T2855 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 873849 T2879 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 873849 T2855 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 873851 T2855 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 873853 T2855 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 873855 T2878 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 873857 T2880 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369022705299/collection1
[junit4:junit4] 2> 873857 T2880 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 873858 T2880 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 873858 T2880 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 873859 T2880 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369022705299/collection1/'
[junit4:junit4] 2> 873859 T2880 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369022705299/collection1/lib/README' to classloader
[junit4:junit4] 2> 873859 T2880 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369022705299/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 873892 T2880 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 873917 T2880 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 873918 T2880 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 873922 T2880 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 874198 T2880 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 874200 T2880 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 874202 T2880 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 874205 T2880 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 874224 T2880 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 874224 T2880 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369022705299/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/control/data/
[junit4:junit4] 2> 874225 T2880 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24a42201
[junit4:junit4] 2> 874225 T2880 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 874225 T2880 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/control/data
[junit4:junit4] 2> 874226 T2880 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/control/data/index/
[junit4:junit4] 2> 874226 T2880 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 874226 T2880 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/control/data/index
[junit4:junit4] 2> 874227 T2880 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b1b9bc7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@237a96ae),segFN=segments_1,generation=1}
[junit4:junit4] 2> 874228 T2880 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 874229 T2880 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 874230 T2880 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 874230 T2880 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 874231 T2880 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 874231 T2880 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 874231 T2880 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 874231 T2880 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 874232 T2880 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 874232 T2880 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 874234 T2880 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 874236 T2880 oass.SolrIndexSearcher.<init> Opening Searcher@14692547 main
[junit4:junit4] 2> 874236 T2880 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/control/data/tlog
[junit4:junit4] 2> 874236 T2880 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 874236 T2880 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 874239 T2881 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14692547 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 874240 T2880 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 874240 T2880 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 875359 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 875360 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:34325_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34325",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 875361 T2878 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 875361 T2878 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 875367 T2877 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> 876243 T2880 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 876243 T2880 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34325 collection:control_collection shard:shard1
[junit4:junit4] 2> 876244 T2880 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 876253 T2880 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 876255 T2880 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 876255 T2880 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 876255 T2880 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:34325/collection1/
[junit4:junit4] 2> 876255 T2880 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 876256 T2880 oasc.SyncStrategy.syncToMe http://127.0.0.1:34325/collection1/ has no replicas
[junit4:junit4] 2> 876256 T2880 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:34325/collection1/
[junit4:junit4] 2> 876256 T2880 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 876871 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 876881 T2877 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> 876912 T2880 oasc.ZkController.register We are http://127.0.0.1:34325/collection1/ and leader is http://127.0.0.1:34325/collection1/
[junit4:junit4] 2> 876912 T2880 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34325
[junit4:junit4] 2> 876912 T2880 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 876913 T2880 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 876913 T2880 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 876915 T2880 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 876916 T2855 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 876916 T2855 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 876916 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 876919 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 876920 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 876921 T2884 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@57c9e925 name:ZooKeeperConnection Watcher:127.0.0.1:43106/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 876922 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 876922 T2855 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 876924 T2855 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 876987 T2855 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 876988 T2855 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:41567
[junit4:junit4] 2> 876989 T2855 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 876990 T2855 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 876990 T2855 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369022708552
[junit4:junit4] 2> 876990 T2855 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369022708552/solr.xml
[junit4:junit4] 2> 876990 T2855 oasc.CoreContainer.<init> New CoreContainer 392150548
[junit4:junit4] 2> 876991 T2855 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369022708552/'
[junit4:junit4] 2> 876991 T2855 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369022708552/'
[junit4:junit4] 2> 877045 T2855 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 877045 T2855 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 877046 T2855 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 877046 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 877046 T2855 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 877047 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 877047 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 877048 T2855 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 877048 T2855 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 877048 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 877052 T2855 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 877053 T2855 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43106/solr
[junit4:junit4] 2> 877053 T2855 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 877053 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 877055 T2895 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b55eb02 name:ZooKeeperConnection Watcher:127.0.0.1:43106 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 877055 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 877056 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 877059 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 877060 T2897 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@986328e name:ZooKeeperConnection Watcher:127.0.0.1:43106/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 877060 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 877063 T2855 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 878066 T2855 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41567_
[junit4:junit4] 2> 878067 T2855 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41567_
[junit4:junit4] 2> 878072 T2884 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 878072 T2877 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 878072 T2897 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 878072 T2877 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> 878076 T2898 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369022708552/collection1
[junit4:junit4] 2> 878076 T2898 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 878077 T2898 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 878077 T2898 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 878078 T2898 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369022708552/collection1/'
[junit4:junit4] 2> 878078 T2898 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369022708552/collection1/lib/README' to classloader
[junit4:junit4] 2> 878078 T2898 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369022708552/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 878103 T2898 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 878131 T2898 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 878132 T2898 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 878136 T2898 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 878387 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 878388 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:34325_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34325",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:34325__collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 878391 T2884 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> 878391 T2877 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> 878391 T2897 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> 878436 T2898 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 878438 T2898 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 878439 T2898 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 878442 T2898 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 878467 T2898 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 878468 T2898 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369022708552/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty1/
[junit4:junit4] 2> 878468 T2898 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24a42201
[junit4:junit4] 2> 878468 T2898 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 878469 T2898 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty1
[junit4:junit4] 2> 878469 T2898 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty1/index/
[junit4:junit4] 2> 878469 T2898 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 878470 T2898 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty1/index
[junit4:junit4] 2> 878471 T2898 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@391267c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@52aa08e3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 878472 T2898 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 878474 T2898 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 878474 T2898 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 878475 T2898 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 878476 T2898 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 878476 T2898 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 878476 T2898 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 878477 T2898 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 878477 T2898 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 878478 T2898 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 878481 T2898 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 878484 T2898 oass.SolrIndexSearcher.<init> Opening Searcher@3aec75f8 main
[junit4:junit4] 2> 878485 T2898 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty1/tlog
[junit4:junit4] 2> 878485 T2898 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 878485 T2898 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 878506 T2899 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3aec75f8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 878509 T2898 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 878509 T2898 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 879896 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 879897 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:41567_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41567",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 879897 T2878 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 879897 T2878 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 879903 T2897 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> 879903 T2884 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> 879903 T2877 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> 880511 T2898 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 880512 T2898 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:41567 collection:collection1 shard:shard2
[junit4:junit4] 2> 880513 T2898 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 880523 T2898 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 880526 T2898 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 880526 T2898 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 880527 T2898 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:41567/collection1/
[junit4:junit4] 2> 880527 T2898 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 880527 T2898 oasc.SyncStrategy.syncToMe http://127.0.0.1:41567/collection1/ has no replicas
[junit4:junit4] 2> 880527 T2898 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:41567/collection1/
[junit4:junit4] 2> 880528 T2898 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 881409 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 881415 T2877 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> 881415 T2884 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> 881415 T2897 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> 881439 T2898 oasc.ZkController.register We are http://127.0.0.1:41567/collection1/ and leader is http://127.0.0.1:41567/collection1/
[junit4:junit4] 2> 881439 T2898 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:41567
[junit4:junit4] 2> 881439 T2898 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 881440 T2898 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 881440 T2898 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 881442 T2898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 881443 T2855 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 881443 T2855 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 881444 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 881508 T2855 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 881510 T2855 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51762
[junit4:junit4] 2> 881511 T2855 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 881511 T2855 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 881511 T2855 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369022713074
[junit4:junit4] 2> 881512 T2855 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369022713074/solr.xml
[junit4:junit4] 2> 881512 T2855 oasc.CoreContainer.<init> New CoreContainer 1187073104
[junit4:junit4] 2> 881512 T2855 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369022713074/'
[junit4:junit4] 2> 881512 T2855 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369022713074/'
[junit4:junit4] 2> 881548 T2855 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 881549 T2855 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 881549 T2855 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 881549 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 881549 T2855 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 881550 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 881550 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 881550 T2855 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 881550 T2855 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 881550 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 881553 T2855 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 881554 T2855 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43106/solr
[junit4:junit4] 2> 881554 T2855 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 881555 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 881556 T2911 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@26876f21 name:ZooKeeperConnection Watcher:127.0.0.1:43106 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 881556 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 881558 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 881560 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 881562 T2913 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1270c1 name:ZooKeeperConnection Watcher:127.0.0.1:43106/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 881562 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 881565 T2855 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 882568 T2855 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51762_
[junit4:junit4] 2> 882570 T2855 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51762_
[junit4:junit4] 2> 882574 T2897 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> 882574 T2884 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> 882575 T2877 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 882576 T2913 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 882576 T2877 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> 882578 T2884 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 882578 T2897 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 882586 T2914 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369022713074/collection1
[junit4:junit4] 2> 882586 T2914 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 882587 T2914 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 882587 T2914 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 882589 T2914 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369022713074/collection1/'
[junit4:junit4] 2> 882590 T2914 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369022713074/collection1/lib/README' to classloader
[junit4:junit4] 2> 882590 T2914 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369022713074/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 882625 T2914 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 882673 T2914 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 882675 T2914 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 882681 T2914 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 882920 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 882921 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:41567_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41567",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:41567__collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 882925 T2884 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> 882925 T2877 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> 882925 T2913 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> 882925 T2897 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> 883021 T2914 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 883024 T2914 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 883026 T2914 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 883029 T2914 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 883050 T2914 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 883051 T2914 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369022713074/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty2/
[junit4:junit4] 2> 883051 T2914 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24a42201
[junit4:junit4] 2> 883051 T2914 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 883051 T2914 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty2
[junit4:junit4] 2> 883052 T2914 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty2/index/
[junit4:junit4] 2> 883052 T2914 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 883052 T2914 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty2/index
[junit4:junit4] 2> 883053 T2914 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4752f3fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b8792e8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 883054 T2914 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 883055 T2914 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 883056 T2914 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 883056 T2914 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 883057 T2914 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 883057 T2914 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 883057 T2914 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 883057 T2914 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 883058 T2914 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 883058 T2914 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 883059 T2914 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 883061 T2914 oass.SolrIndexSearcher.<init> Opening Searcher@752c7954 main
[junit4:junit4] 2> 883062 T2914 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty2/tlog
[junit4:junit4] 2> 883062 T2914 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 883062 T2914 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 883066 T2915 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@752c7954 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 883067 T2914 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 883068 T2914 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 884431 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 884431 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:51762_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51762",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 884432 T2878 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 884432 T2878 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 884434 T2884 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> 884434 T2913 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> 884434 T2897 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> 884434 T2877 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> 885069 T2914 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 885069 T2914 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51762 collection:collection1 shard:shard1
[junit4:junit4] 2> 885071 T2914 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 885081 T2914 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 885085 T2914 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 885085 T2914 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 885086 T2914 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51762/collection1/
[junit4:junit4] 2> 885086 T2914 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 885086 T2914 oasc.SyncStrategy.syncToMe http://127.0.0.1:51762/collection1/ has no replicas
[junit4:junit4] 2> 885086 T2914 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51762/collection1/
[junit4:junit4] 2> 885087 T2914 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 885940 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 885948 T2884 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> 885949 T2913 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> 885949 T2897 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> 885949 T2877 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> 885997 T2914 oasc.ZkController.register We are http://127.0.0.1:51762/collection1/ and leader is http://127.0.0.1:51762/collection1/
[junit4:junit4] 2> 885997 T2914 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51762
[junit4:junit4] 2> 885997 T2914 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 885997 T2914 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 885998 T2914 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 886000 T2914 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 886002 T2855 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 886003 T2855 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 886003 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 886081 T2855 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 886083 T2855 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:34281
[junit4:junit4] 2> 886084 T2855 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 886085 T2855 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 886085 T2855 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369022717637
[junit4:junit4] 2> 886085 T2855 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369022717637/solr.xml
[junit4:junit4] 2> 886085 T2855 oasc.CoreContainer.<init> New CoreContainer 409389209
[junit4:junit4] 2> 886086 T2855 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369022717637/'
[junit4:junit4] 2> 886086 T2855 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369022717637/'
[junit4:junit4] 2> 886122 T2855 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 886123 T2855 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 886123 T2855 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 886123 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 886123 T2855 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 886123 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 886124 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 886124 T2855 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 886124 T2855 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 886124 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 886127 T2855 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 886128 T2855 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43106/solr
[junit4:junit4] 2> 886128 T2855 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 886129 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 886130 T2927 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e2a1d4c name:ZooKeeperConnection Watcher:127.0.0.1:43106 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 886131 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 886132 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 886137 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 886138 T2929 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@575a91d6 name:ZooKeeperConnection Watcher:127.0.0.1:43106/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 886138 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 886141 T2855 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 887143 T2855 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34281_
[junit4:junit4] 2> 887145 T2855 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34281_
[junit4:junit4] 2> 887149 T2897 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> 887149 T2884 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> 887149 T2913 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 887149 T2877 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 887149 T2913 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> 887149 T2929 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 887149 T2877 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> 887151 T2884 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 887151 T2897 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 887157 T2930 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369022717637/collection1
[junit4:junit4] 2> 887157 T2930 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 887178 T2930 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 887178 T2930 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 887180 T2930 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369022717637/collection1/'
[junit4:junit4] 2> 887181 T2930 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369022717637/collection1/lib/README' to classloader
[junit4:junit4] 2> 887181 T2930 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369022717637/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 887218 T2930 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 887243 T2930 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 887245 T2930 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 887248 T2930 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 887455 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 887456 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:51762_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51762",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51762__collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 887459 T2897 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> 887459 T2929 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> 887459 T2877 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> 887459 T2884 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> 887459 T2913 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> 887540 T2930 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 887542 T2930 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 887543 T2930 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 887547 T2930 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 887566 T2930 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 887567 T2930 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369022717637/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty3/
[junit4:junit4] 2> 887567 T2930 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24a42201
[junit4:junit4] 2> 887567 T2930 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 887568 T2930 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty3
[junit4:junit4] 2> 887568 T2930 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty3/index/
[junit4:junit4] 2> 887568 T2930 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 887569 T2930 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty3/index
[junit4:junit4] 2> 887571 T2930 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6bbf7930 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7176d292),segFN=segments_1,generation=1}
[junit4:junit4] 2> 887571 T2930 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 887573 T2930 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 887574 T2930 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 887574 T2930 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 887575 T2930 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 887575 T2930 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 887575 T2930 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 887576 T2930 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 887576 T2930 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 887576 T2930 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 887578 T2930 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 887580 T2930 oass.SolrIndexSearcher.<init> Opening Searcher@51bc9b0b main
[junit4:junit4] 2> 887580 T2930 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty3/tlog
[junit4:junit4] 2> 887581 T2930 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 887581 T2930 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 887584 T2931 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@51bc9b0b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 887586 T2930 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 887586 T2930 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 888963 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 888964 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:34281_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34281",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 888964 T2878 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 888964 T2878 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 888968 T2913 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> 888968 T2877 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> 888968 T2884 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> 888968 T2929 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> 888968 T2897 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> 889587 T2930 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 889588 T2930 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34281 collection:collection1 shard:shard2
[junit4:junit4] 2> 889592 T2930 oasc.ZkController.register We are http://127.0.0.1:34281/collection1/ and leader is http://127.0.0.1:41567/collection1/
[junit4:junit4] 2> 889592 T2930 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34281
[junit4:junit4] 2> 889592 T2930 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 889593 T2930 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C240 name=collection1 org.apache.solr.core.SolrCore@2d1bed34 url=http://127.0.0.1:34281/collection1 node=127.0.0.1:34281_ C240_STATE=coll:collection1 core:collection1 props:{core=collection1, node_name=127.0.0.1:34281_, base_url=http://127.0.0.1:34281, collection=collection1, state=down}
[junit4:junit4] 2> 889593 T2932 C240 P34281 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 889594 T2930 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 889594 T2932 C240 P34281 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 889595 T2932 C240 P34281 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 889595 T2932 C240 P34281 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 889596 T2855 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 889596 T2855 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 889596 T2932 C240 P34281 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 889597 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 889605 T2893 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:34281__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 889668 T2855 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 889670 T2855 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35434
[junit4:junit4] 2> 889671 T2855 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 889671 T2855 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 889671 T2855 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369022721231
[junit4:junit4] 2> 889671 T2855 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369022721231/solr.xml
[junit4:junit4] 2> 889672 T2855 oasc.CoreContainer.<init> New CoreContainer 996149200
[junit4:junit4] 2> 889672 T2855 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369022721231/'
[junit4:junit4] 2> 889672 T2855 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369022721231/'
[junit4:junit4] 2> 889737 T2855 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 889737 T2855 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 889737 T2855 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 889738 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 889738 T2855 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 889738 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 889738 T2855 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 889739 T2855 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 889739 T2855 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 889739 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 889742 T2855 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 889742 T2855 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43106/solr
[junit4:junit4] 2> 889742 T2855 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 889743 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 889745 T2944 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7cac5aed name:ZooKeeperConnection Watcher:127.0.0.1:43106 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 889745 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 889747 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 889751 T2855 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 889752 T2946 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@140b259f name:ZooKeeperConnection Watcher:127.0.0.1:43106/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 889753 T2855 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 889756 T2855 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 890473 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 890475 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:34281_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34281",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:34281__collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 890481 T2946 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> 890481 T2897 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> 890483 T2884 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> 890482 T2877 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> 890481 T2929 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> 890481 T2913 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> 890605 T2893 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:34281__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 890606 T2893 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:34281__collection1&checkLive=true&nodeName=127.0.0.1:34281_&core=collection1&action=PREPRECOVERY&version=2&wt=javabin&onlyIfLeader=true&state=recovering} status=0 QTime=1001
[junit4:junit4] 2> 890759 T2855 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35434_
[junit4:junit4] 2> 890761 T2855 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35434_
[junit4:junit4] 2> 890763 T2913 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> 890764 T2897 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> 890764 T2884 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> 890764 T2877 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> 890764 T2946 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 890764 T2929 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 890765 T2946 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> 890765 T2929 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> 890766 T2913 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 890767 T2897 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 890768 T2877 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 890768 T2884 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 890774 T2947 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369022721231/collection1
[junit4:junit4] 2> 890775 T2947 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 890776 T2947 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 890776 T2947 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 890778 T2947 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369022721231/collection1/'
[junit4:junit4] 2> 890778 T2947 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369022721231/collection1/lib/README' to classloader
[junit4:junit4] 2> 890779 T2947 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369022721231/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 890818 T2947 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 890846 T2947 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 890847 T2947 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 890850 T2947 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 891156 T2947 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 891178 T2947 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 891181 T2947 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 891186 T2947 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 891219 T2947 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 891219 T2947 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369022721231/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/
[junit4:junit4] 2> 891220 T2947 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@24a42201
[junit4:junit4] 2> 891220 T2947 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 891221 T2947 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4
[junit4:junit4] 2> 891221 T2947 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/index/
[junit4:junit4] 2> 891221 T2947 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 891222 T2947 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/index
[junit4:junit4] 2> 891225 T2947 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b607299 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7f6247e3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 891225 T2947 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 891228 T2947 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 891228 T2947 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 891229 T2947 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 891230 T2947 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 891231 T2947 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 891231 T2947 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 891232 T2947 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 891232 T2947 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 891233 T2947 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 891236 T2947 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 891240 T2947 oass.SolrIndexSearcher.<init> Opening Searcher@16b50202 main
[junit4:junit4] 2> 891240 T2947 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/tlog
[junit4:junit4] 2> 891241 T2947 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 891241 T2947 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 891247 T2948 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16b50202 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 891250 T2947 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 891250 T2947 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 891990 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 891991 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:35434_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35434",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 891991 T2878 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 891992 T2878 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 891997 T2913 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> 891998 T2884 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> 891998 T2897 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> 891998 T2877 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> 891997 T2929 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> 891997 T2946 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> 892253 T2947 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 892254 T2947 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35434 collection:collection1 shard:shard1
[junit4:junit4] 2> 892258 T2947 oasc.ZkController.register We are http://127.0.0.1:35434/collection1/ and leader is http://127.0.0.1:51762/collection1/
[junit4:junit4] 2> 892258 T2947 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35434
[junit4:junit4] 2> 892259 T2947 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 892259 T2947 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C241 name=collection1 org.apache.solr.core.SolrCore@1db39014 url=http://127.0.0.1:35434/collection1 node=127.0.0.1:35434_ C241_STATE=coll:collection1 core:collection1 props:{core=collection1, node_name=127.0.0.1:35434_, base_url=http://127.0.0.1:35434, collection=collection1, state=down}
[junit4:junit4] 2> 892260 T2949 C241 P35434 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 892261 T2949 C241 P35434 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 892261 T2947 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 892261 T2949 C241 P35434 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 892262 T2949 C241 P35434 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 892263 T2855 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 892264 T2855 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 892264 T2949 C241 P35434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 892264 T2855 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 892271 T2855 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 892272 T2908 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:35434__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 892272 T2855 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 892272 T2855 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 892273 T2855 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C240_STATE=coll:collection1 core:collection1 props:{core=collection1, node_name=127.0.0.1:34281_, base_url=http://127.0.0.1:34281, collection=collection1, shard=shard2, state=recovering}
[junit4:junit4] 2> 892607 T2932 C240 P34281 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:41567/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 892607 T2932 C240 P34281 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34281 START replicas=[http://127.0.0.1:41567/collection1/] nUpdates=100
[junit4:junit4] 2> 892608 T2932 C240 P34281 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 892609 T2932 C240 P34281 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 892609 T2932 C240 P34281 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 892609 T2932 C240 P34281 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 892610 T2932 C240 P34281 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 892610 T2932 C240 P34281 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:41567/collection1/. core=collection1
[junit4:junit4] 2> 892610 T2932 C240 P34281 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C242 name=collection1 org.apache.solr.core.SolrCore@11f92deb url=http://127.0.0.1:41567/collection1 node=127.0.0.1:41567_ C242_STATE=coll:collection1 core:collection1 props:{core=collection1, node_name=127.0.0.1:41567_, base_url=http://127.0.0.1:41567, collection=collection1, shard=shard2, state=active, leader=true}
[junit4:junit4] 2> 892617 T2890 C242 P41567 oasc.SolrCore.execute [collection1] webapp= path=/get params={distrib=false&version=2&wt=javabin&getVersions=100&qt=/get} status=0 QTime=1
[junit4:junit4] 2> 892618 T2892 C242 P41567 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 892620 T2892 C242 P41567 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@391267c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@52aa08e3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 892621 T2892 C242 P41567 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 892623 T2892 C242 P41567 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@391267c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@52aa08e3),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@391267c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@52aa08e3),segFN=segments_2,generation=2}
[junit4:junit4] 2> 892623 T2892 C242 P41567 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 892624 T2892 C242 P41567 oass.SolrIndexSearcher.<init> Opening Searcher@4623464b realtime
[junit4:junit4] 2> 892624 T2892 C242 P41567 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 892625 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&commit_end_point=true&waitSearcher=true&wt=javabin&softCommit=false&commit=true&openSearcher=false} {commit=} 0 7
[junit4:junit4] 2> 892626 T2932 C240 P34281 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 892626 T2932 C240 P34281 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 892633 T2891 C242 P41567 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 892633 T2891 C242 P41567 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&version=2&wt=javabin&qt=/replication} status=0 QTime=5
[junit4:junit4] 2> 892634 T2932 C240 P34281 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 892634 T2932 C240 P34281 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 892634 T2932 C240 P34281 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 892636 T2890 C242 P41567 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&version=2&generation=2&wt=javabin&qt=/replication} status=0 QTime=0
[junit4:junit4] 2> 892637 T2932 C240 P34281 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 892638 T2932 C240 P34281 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty3/index.20130520110524266
[junit4:junit4] 2> 892639 T2932 C240 P34281 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@54c6bcab lockFactory=org.apache.lucene.store.NativeFSLockFactory@f815e93) fullCopy=false
[junit4:junit4] 2> 892641 T2892 C242 P41567 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&generation=2&wt=filestream&checksum=true&qt=/replication} status=0 QTime=0
[junit4:junit4] 2> 892642 T2932 C240 P34281 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 892643 T2932 C240 P34281 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 892644 T2932 C240 P34281 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 892645 T2932 C240 P34281 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6bbf7930 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7176d292),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6bbf7930 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7176d292),segFN=segments_2,generation=2}
[junit4:junit4] 2> 892646 T2932 C240 P34281 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 892646 T2932 C240 P34281 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 892647 T2932 C240 P34281 oass.SolrIndexSearcher.<init> Opening Searcher@2ee417d2 main
[junit4:junit4] 2> 892648 T2931 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2ee417d2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 892649 T2932 C240 P34281 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty3/index.20130520110524266 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty3/index.20130520110524266;done=true>>]
[junit4:junit4] 2> 892649 T2932 C240 P34281 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty3/index.20130520110524266
[junit4:junit4] 2> 892649 T2932 C240 P34281 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty3/index.20130520110524266
[junit4:junit4] 2> 892650 T2932 C240 P34281 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 892650 T2932 C240 P34281 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 892650 T2932 C240 P34281 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 892650 T2932 C240 P34281 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 892652 T2932 C240 P34281 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 893275 T2855 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 893503 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 893504 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:35434_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35434",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:35434__collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 893507 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:34281_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34281",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:34281__collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 893510 T2897 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> 893510 T2884 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> 893510 T2877 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> 893510 T2929 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> 893510 T2913 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> 893511 T2946 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> 894272 T2908 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:35434__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 894272 T2908 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:35434__collection1&checkLive=true&nodeName=127.0.0.1:35434_&core=collection1&action=PREPRECOVERY&version=2&wt=javabin&onlyIfLeader=true&state=recovering} status=0 QTime=2001
[junit4:junit4] 2> 894276 T2855 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 895278 T2855 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C241_STATE=coll:collection1 core:collection1 props:{core=collection1, node_name=127.0.0.1:35434_, base_url=http://127.0.0.1:35434, collection=collection1, shard=shard1, state=recovering}
[junit4:junit4] 2> 896273 T2949 C241 P35434 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:51762/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 896273 T2949 C241 P35434 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:35434 START replicas=[http://127.0.0.1:51762/collection1/] nUpdates=100
[junit4:junit4] 2> 896274 T2949 C241 P35434 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 896274 T2949 C241 P35434 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 896274 T2949 C241 P35434 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 896274 T2949 C241 P35434 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 896274 T2949 C241 P35434 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 896274 T2949 C241 P35434 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:51762/collection1/. core=collection1
[junit4:junit4] 2> 896275 T2949 C241 P35434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C243 name=collection1 org.apache.solr.core.SolrCore@4d1b7c44 url=http://127.0.0.1:51762/collection1 node=127.0.0.1:51762_ C243_STATE=coll:collection1 core:collection1 props:{core=collection1, node_name=127.0.0.1:51762_, base_url=http://127.0.0.1:51762, collection=collection1, shard=shard1, state=active, leader=true}
[junit4:junit4] 2> 896278 T2908 C243 P51762 oasc.SolrCore.execute [collection1] webapp= path=/get params={distrib=false&version=2&wt=javabin&getVersions=100&qt=/get} status=0 QTime=0
[junit4:junit4] 2> 896280 T2855 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 896282 T2906 C243 P51762 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 896285 T2906 C243 P51762 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4752f3fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b8792e8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 896286 T2906 C243 P51762 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 896287 T2906 C243 P51762 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4752f3fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b8792e8),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4752f3fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b8792e8),segFN=segments_2,generation=2}
[junit4:junit4] 2> 896287 T2906 C243 P51762 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 896287 T2906 C243 P51762 oass.SolrIndexSearcher.<init> Opening Searcher@2f581dd6 realtime
[junit4:junit4] 2> 896288 T2906 C243 P51762 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 896288 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&commit_end_point=true&waitSearcher=true&wt=javabin&softCommit=false&commit=true&openSearcher=false} {commit=} 0 6
[junit4:junit4] 2> 896289 T2949 C241 P35434 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 896289 T2949 C241 P35434 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 896291 T2909 C243 P51762 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 896291 T2909 C243 P51762 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&version=2&wt=javabin&qt=/replication} status=0 QTime=1
[junit4:junit4] 2> 896292 T2949 C241 P35434 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 896292 T2949 C241 P35434 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 896292 T2949 C241 P35434 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 896294 T2908 C243 P51762 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&version=2&generation=2&wt=javabin&qt=/replication} status=0 QTime=0
[junit4:junit4] 2> 896294 T2949 C241 P35434 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 896296 T2949 C241 P35434 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/index.20130520110527923
[junit4:junit4] 2> 896296 T2949 C241 P35434 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@596b2c06 lockFactory=org.apache.lucene.store.NativeFSLockFactory@10638aa6) fullCopy=false
[junit4:junit4] 2> 896298 T2906 C243 P51762 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&generation=2&wt=filestream&checksum=true&qt=/replication} status=0 QTime=0
[junit4:junit4] 2> 896299 T2949 C241 P35434 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 896300 T2949 C241 P35434 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 896300 T2949 C241 P35434 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 896301 T2949 C241 P35434 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b607299 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7f6247e3),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b607299 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7f6247e3),segFN=segments_2,generation=2}
[junit4:junit4] 2> 896302 T2949 C241 P35434 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 896302 T2949 C241 P35434 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 896302 T2949 C241 P35434 oass.SolrIndexSearcher.<init> Opening Searcher@2c582f50 main
[junit4:junit4] 2> 896303 T2948 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2c582f50 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 896304 T2949 C241 P35434 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/index.20130520110527923 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/index.20130520110527923;done=true>>]
[junit4:junit4] 2> 896304 T2949 C241 P35434 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/index.20130520110527923
[junit4:junit4] 2> 896304 T2949 C241 P35434 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/index.20130520110527923
[junit4:junit4] 2> 896304 T2949 C241 P35434 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 896304 T2949 C241 P35434 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 896305 T2949 C241 P35434 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 896305 T2949 C241 P35434 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 896306 T2949 C241 P35434 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 896517 T2878 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 896518 T2878 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:35434_",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35434",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:35434__collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active"}
[junit4:junit4] 2> 896520 T2946 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> 896520 T2884 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> 896520 T2897 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> 896520 T2929 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> 896520 T2913 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> 896521 T2877 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> 897281 T2855 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 897282 T2855 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C244 name=collection1 org.apache.solr.core.SolrCore@62ae935a url=http://127.0.0.1:34325/collection1 node=127.0.0.1:34325_ C244_STATE=coll:control_collection core:collection1 props:{core=collection1, node_name=127.0.0.1:34325_, base_url=http://127.0.0.1:34325, collection=control_collection, shard=shard1, state=active, leader=true}
[junit4:junit4] 2> 897287 T2871 C244 P34325 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 897289 T2871 C244 P34325 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b1b9bc7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@237a96ae),segFN=segments_1,generation=1}
[junit4:junit4] 2> 897290 T2871 C244 P34325 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 897291 T2871 C244 P34325 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b1b9bc7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@237a96ae),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b1b9bc7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@237a96ae),segFN=segments_2,generation=2}
[junit4:junit4] 2> 897291 T2871 C244 P34325 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 897291 T2871 C244 P34325 oass.SolrIndexSearcher.<init> Opening Searcher@5c9dbc7b main
[junit4:junit4] 2> 897292 T2871 C244 P34325 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 897292 T2881 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c9dbc7b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 897293 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&waitSearcher=true&wt=javabin&softCommit=false&commit=true} {commit=} 0 6
[junit4:junit4] 2> 897296 T2890 C242 P41567 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 897297 T2890 C242 P41567 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@391267c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@52aa08e3),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@391267c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@52aa08e3),segFN=segments_3,generation=3}
[junit4:junit4] 2> 897297 T2890 C242 P41567 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 897298 T2890 C242 P41567 oass.SolrIndexSearcher.<init> Opening Searcher@2a05a1d0 main
[junit4:junit4] 2> 897298 T2890 C242 P41567 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 897298 T2899 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2a05a1d0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 897299 T2890 C242 P41567 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:51762/collection1/, StdNode: http://127.0.0.1:35434/collection1/, StdNode: http://127.0.0.1:34281/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 897301 T2906 C243 P51762 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 897302 T2906 C243 P51762 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4752f3fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b8792e8),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4752f3fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b8792e8),segFN=segments_3,generation=3}
[junit4:junit4] 2> 897302 T2906 C243 P51762 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 897303 T2906 C243 P51762 oass.SolrIndexSearcher.<init> Opening Searcher@ac87fb1 main
[junit4:junit4] 2> 897303 T2906 C243 P51762 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 897304 T2915 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ac87fb1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> C240_STATE=coll:collection1 core:collection1 props:{core=collection1, node_name=127.0.0.1:34281_, base_url=http://127.0.0.1:34281, collection=collection1, shard=shard2, state=active}
[junit4:junit4] 2> 897304 T2925 C240 P34281 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 897305 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&commit_end_point=true&waitSearcher=true&wt=javabin&softCommit=false&commit=true&expungeDeletes=false} {commit=} 0 4
[junit4:junit4] 2> 897306 T2925 C240 P34281 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6bbf7930 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7176d292),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6bbf7930 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7176d292),segFN=segments_3,generation=3}
[junit4:junit4] 2> 897306 T2925 C240 P34281 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> C241_STATE=coll:collection1 core:collection1 props:{core=collection1, node_name=127.0.0.1:35434_, base_url=http://127.0.0.1:35434, collection=collection1, shard=shard1, state=active}
[junit4:junit4] 2> 897306 T2940 C241 P35434 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 897307 T2925 C240 P34281 oass.SolrIndexSearcher.<init> Opening Searcher@71f221a4 main
[junit4:junit4] 2> 897308 T2940 C241 P35434 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b607299 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7f6247e3),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b607299 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7f6247e3),segFN=segments_3,generation=3}
[junit4:junit4] 2> 897309 T2940 C241 P35434 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 897308 T2925 C240 P34281 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 897309 T2940 C241 P35434 oass.SolrIndexSearcher.<init> Opening Searcher@413da4be main
[junit4:junit4] 2> 897309 T2931 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@71f221a4 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 897310 T2940 C241 P35434 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 897310 T2925 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&commit_end_point=true&waitSearcher=true&wt=javabin&softCommit=false&commit=true&expungeDeletes=false} {commit=} 0 6
[junit4:junit4] 2> 897311 T2948 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@413da4be main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 897311 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&commit_end_point=true&waitSearcher=true&wt=javabin&softCommit=false&commit=true&expungeDeletes=false} {commit=} 0 5
[junit4:junit4] 2> 897312 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&waitSearcher=true&wt=javabin&softCommit=false&commit=true} {commit=} 0 16
[junit4:junit4] 2> 897312 T2855 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 897314 T2892 C242 P41567 oasc.SolrCore.execute [collection1] webapp= path=/select params={distrib=false&q=*:*&version=2&tests=checkShardConsistency&wt=javabin&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 897315 T2922 C240 P34281 oasc.SolrCore.execute [collection1] webapp= path=/select params={distrib=false&q=*:*&version=2&tests=checkShardConsistency&wt=javabin&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 897317 T2909 C243 P51762 oasc.SolrCore.execute [collection1] webapp= path=/select params={distrib=false&q=*:*&version=2&tests=checkShardConsistency&wt=javabin&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 897318 T2942 C241 P35434 oasc.SolrCore.execute [collection1] webapp= path=/select params={distrib=false&q=*:*&version=2&tests=checkShardConsistency&wt=javabin&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 899323 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1435524379127578624)} 0 2
[junit4:junit4] 2> 899332 T2941 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={_version_=-1435524379132821504&version=2&update.distrib=FROMLEADER&update.from=http://127.0.0.1:51762/collection1/&wt=javabin} {deleteByQuery=*:* (-1435524379132821504)} 0 1
[junit4:junit4] 2> 899335 T2922 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={_version_=-1435524379138064384&version=2&update.distrib=FROMLEADER&update.from=http://127.0.0.1:41567/collection1/&wt=javabin} {deleteByQuery=*:* (-1435524379138064384)} 0 1
[junit4:junit4] 2> 899336 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&update.distrib=TOLEADER&wt=javabin} {deleteByQuery=*:* (-1435524379138064384)} 0 5
[junit4:junit4] 2> 899337 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1435524379132821504)} 0 11
[junit4:junit4] 2> 899340 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[0 (1435524379146452992)]} 0 1
[junit4:junit4] 2> 899349 T2942 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[0 (1435524379152744448)]} 0 1
[junit4:junit4] 2> 899350 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[0 (1435524379152744448)]} 0 5
[junit4:junit4] 2> 899350 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[0]} 0 8
[junit4:junit4] 2> 899353 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[1 (1435524379161133056)]} 0 0
[junit4:junit4] 2> 899361 T2938 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[1 (1435524379166375936)]} 0 1
[junit4:junit4] 2> 899362 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[1 (1435524379166375936)]} 0 4
[junit4:junit4] 2> 899362 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[1]} 0 6
[junit4:junit4] 2> 899365 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[2 (1435524379173715968)]} 0 0
[junit4:junit4] 2> 899371 T2924 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[2 (1435524379176861696)]} 0 0
[junit4:junit4] 2> 899372 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[2 (1435524379176861696)]} 0 4
[junit4:junit4] 2> 899374 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[3 (1435524379183153152)]} 0 0
[junit4:junit4] 2> 899380 T2925 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[3 (1435524379187347456)]} 0 1
[junit4:junit4] 2> 899380 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[3 (1435524379187347456)]} 0 3
[junit4:junit4] 2> 899380 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[3]} 0 4
[junit4:junit4] 2> 899383 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[4 (1435524379191541760)]} 0 1
[junit4:junit4] 2> 899390 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[4 (1435524379196784640)]} 0 1
[junit4:junit4] 2> 899390 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[4 (1435524379196784640)]} 0 4
[junit4:junit4] 2> 899391 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[4]} 0 7
[junit4:junit4] 2> 899393 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[5 (1435524379203076096)]} 0 0
[junit4:junit4] 2> 899397 T2923 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[5 (1435524379205173248)]} 0 0
[junit4:junit4] 2> 899398 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[5 (1435524379205173248)]} 0 3
[junit4:junit4] 2> 899400 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[6 (1435524379210416128)]} 0 1
[junit4:junit4] 2> 899404 T2922 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[6 (1435524379212513280)]} 0 1
[junit4:junit4] 2> 899404 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[6 (1435524379212513280)]} 0 2
[junit4:junit4] 2> 899406 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[7 (1435524379216707584)]} 0 0
[junit4:junit4] 2> 899412 T2924 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[7 (1435524379220901888)]} 0 0
[junit4:junit4] 2> 899412 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[7 (1435524379220901888)]} 0 2
[junit4:junit4] 2> 899413 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[7]} 0 5
[junit4:junit4] 2> 899415 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[8 (1435524379226144768)]} 0 0
[junit4:junit4] 2> 899421 T2941 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[8 (1435524379230339072)]} 0 1
[junit4:junit4] 2> 899421 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[8 (1435524379230339072)]} 0 2
[junit4:junit4] 2> 899422 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[8]} 0 5
[junit4:junit4] 2> 899424 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[9 (1435524379235581952)]} 0 0
[junit4:junit4] 2> 899428 T2925 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[9 (1435524379237679104)]} 0 0
[junit4:junit4] 2> 899428 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[9 (1435524379237679104)]} 0 2
[junit4:junit4] 2> 899431 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[10 (1435524379242921984)]} 0 0
[junit4:junit4] 2> 899435 T2942 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[10 (1435524379245019136)]} 0 0
[junit4:junit4] 2> 899435 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[10 (1435524379245019136)]} 0 2
[junit4:junit4] 2> 899437 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[11 (1435524379249213440)]} 0 0
[junit4:junit4] 2> 899443 T2938 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[11 (1435524379253407744)]} 0 1
[junit4:junit4] 2> 899443 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[11 (1435524379253407744)]} 0 2
[junit4:junit4] 2> 899443 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[11]} 0 4
[junit4:junit4] 2> 899445 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[12 (1435524379257602048)]} 0 0
[junit4:junit4] 2> 899451 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[12 (1435524379261796352)]} 0 0
[junit4:junit4] 2> 899452 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[12 (1435524379261796352)]} 0 3
[junit4:junit4] 2> 899452 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[12]} 0 5
[junit4:junit4] 2> 899454 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[13 (1435524379267039232)]} 0 0
[junit4:junit4] 2> 899461 T2941 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[13 (1435524379271233536)]} 0 1
[junit4:junit4] 2> 899462 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[13 (1435524379271233536)]} 0 4
[junit4:junit4] 2> 899462 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[13]} 0 6
[junit4:junit4] 2> 899465 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[14 (1435524379278573568)]} 0 1
[junit4:junit4] 2> 899470 T2942 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[14 (1435524379280670720)]} 0 0
[junit4:junit4] 2> 899471 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[14 (1435524379280670720)]} 0 4
[junit4:junit4] 2> 899473 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[15 (1435524379285913600)]} 0 1
[junit4:junit4] 2> 899478 T2938 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[15 (1435524379290107904)]} 0 0
[junit4:junit4] 2> 899478 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[15 (1435524379290107904)]} 0 2
[junit4:junit4] 2> 899479 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[15]} 0 5
[junit4:junit4] 2> 899481 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[16 (1435524379295350784)]} 0 1
[junit4:junit4] 2> 899485 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[16 (1435524379297447936)]} 0 0
[junit4:junit4] 2> 899485 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[16 (1435524379297447936)]} 0 2
[junit4:junit4] 2> 899488 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[17 (1435524379301642240)]} 0 1
[junit4:junit4] 2> 899493 T2923 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[17 (1435524379305836544)]} 0 0
[junit4:junit4] 2> 899494 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[17 (1435524379305836544)]} 0 3
[junit4:junit4] 2> 899494 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[17]} 0 5
[junit4:junit4] 2> 899497 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[18 (1435524379311079424)]} 0 1
[junit4:junit4] 2> 899503 T2922 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[18 (1435524379316322304)]} 0 0
[junit4:junit4] 2> 899504 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[18 (1435524379316322304)]} 0 3
[junit4:junit4] 2> 899505 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[18]} 0 7
[junit4:junit4] 2> 899508 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[19 (1435524379323662336)]} 0 1
[junit4:junit4] 2> 899512 T2924 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[19 (1435524379325759488)]} 0 0
[junit4:junit4] 2> 899513 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[19 (1435524379325759488)]} 0 3
[junit4:junit4] 2> 899515 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[20 (1435524379331002368)]} 0 0
[junit4:junit4] 2> 899523 T2941 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[20 (1435524379335196672)]} 0 1
[junit4:junit4] 2> 899525 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[20 (1435524379335196672)]} 0 6
[junit4:junit4] 2> 899526 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[20]} 0 9
[junit4:junit4] 2> 899529 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[21 (1435524379344633856)]} 0 1
[junit4:junit4] 2> 899536 T2925 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[21 (1435524379350925312)]} 0 0
[junit4:junit4] 2> 899537 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[21 (1435524379350925312)]} 0 3
[junit4:junit4] 2> 899537 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[21]} 0 6
[junit4:junit4] 2> 899539 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[22 (1435524379356168192)]} 0 0
[junit4:junit4] 2> 899543 T2942 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[22 (1435524379358265344)]} 0 0
[junit4:junit4] 2> 899543 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[22 (1435524379358265344)]} 0 2
[junit4:junit4] 2> 899545 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[23 (1435524379362459648)]} 0 0
[junit4:junit4] 2> 899551 T2923 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[23 (1435524379366653952)]} 0 1
[junit4:junit4] 2> 899551 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[23 (1435524379366653952)]} 0 2
[junit4:junit4] 2> 899552 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[23]} 0 5
[junit4:junit4] 2> 899554 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[24 (1435524379371896832)]} 0 1
[junit4:junit4] 2> 899558 T2938 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[24 (1435524379373993984)]} 0 0
[junit4:junit4] 2> 899558 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[24 (1435524379373993984)]} 0 2
[junit4:junit4] 2> 899560 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[25 (1435524379378188288)]} 0 0
[junit4:junit4] 2> 899564 T2922 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[25 (1435524379380285440)]} 0 0
[junit4:junit4] 2> 899565 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[25 (1435524379380285440)]} 0 3
[junit4:junit4] 2> 899567 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[26 (1435524379384479744)]} 0 1
[junit4:junit4] 2> 899572 T2924 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[26 (1435524379388674048)]} 0 0
[junit4:junit4] 2> 899572 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[26 (1435524379388674048)]} 0 2
[junit4:junit4] 2> 899573 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[26]} 0 5
[junit4:junit4] 2> 899575 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[27 (1435524379393916928)]} 0 0
[junit4:junit4] 2> 899581 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[27 (1435524379398111232)]} 0 1
[junit4:junit4] 2> 899581 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[27 (1435524379398111232)]} 0 2
[junit4:junit4] 2> 899582 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[27]} 0 5
[junit4:junit4] 2> 899584 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[28 (1435524379402305536)]} 0 1
[junit4:junit4] 2> 899591 T2941 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[28 (1435524379407548416)]} 0 1
[junit4:junit4] 2> 899591 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[28 (1435524379407548416)]} 0 3
[junit4:junit4] 2> 899591 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[28]} 0 5
[junit4:junit4] 2> 899593 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[29 (1435524379412791296)]} 0 0
[junit4:junit4] 2> 899599 T2925 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[29 (1435524379416985600)]} 0 0
[junit4:junit4] 2> 899599 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[29 (1435524379416985600)]} 0 2
[junit4:junit4] 2> 899600 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[29]} 0 5
[junit4:junit4] 2> 899602 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[30 (1435524379422228480)]} 0 1
[junit4:junit4] 2> 899606 T2923 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[30 (1435524379424325632)]} 0 1
[junit4:junit4] 2> 899606 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[30 (1435524379424325632)]} 0 2
[junit4:junit4] 2> 899608 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[31 (1435524379428519936)]} 0 0
[junit4:junit4] 2> 899613 T2922 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[31 (1435524379432714240)]} 0 0
[junit4:junit4] 2> 899614 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[31 (1435524379432714240)]} 0 3
[junit4:junit4] 2> 899614 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[31]} 0 4
[junit4:junit4] 2> 899616 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[32 (1435524379436908544)]} 0 0
[junit4:junit4] 2> 899622 T2942 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[32 (1435524379441102848)]} 0 1
[junit4:junit4] 2> 899622 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[32 (1435524379441102848)]} 0 2
[junit4:junit4] 2> 899623 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[32]} 0 5
[junit4:junit4] 2> 899625 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[33 (1435524379445297152)]} 0 1
[junit4:junit4] 2> 899630 T2924 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[33 (1435524379449491456)]} 0 0
[junit4:junit4] 2> 899630 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[33 (1435524379449491456)]} 0 2
[junit4:junit4] 2> 899631 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[33]} 0 5
[junit4:junit4] 2> 899633 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[34 (1435524379454734336)]} 0 1
[junit4:junit4] 2> 899637 T2938 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[34 (1435524379456831488)]} 0 0
[junit4:junit4] 2> 899637 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[34 (1435524379456831488)]} 0 3
[junit4:junit4] 2> 899640 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[35 (1435524379462074368)]} 0 0
[junit4:junit4] 2> 899644 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[35 (1435524379464171520)]} 0 0
[junit4:junit4] 2> 899645 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[35 (1435524379464171520)]} 0 3
[junit4:junit4] 2> 899647 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[36 (1435524379469414400)]} 0 0
[junit4:junit4] 2> 899651 T2941 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[36 (1435524379471511552)]} 0 0
[junit4:junit4] 2> 899651 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[36 (1435524379471511552)]} 0 2
[junit4:junit4] 2> 899653 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[37 (1435524379475705856)]} 0 0
[junit4:junit4] 2> 899659 T2925 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[37 (1435524379479900160)]} 0 0
[junit4:junit4] 2> 899660 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[37 (1435524379479900160)]} 0 3
[junit4:junit4] 2> 899660 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[37]} 0 5
[junit4:junit4] 2> 899662 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[38 (1435524379485143040)]} 0 0
[junit4:junit4] 2> 899666 T2942 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[38 (1435524379487240192)]} 0 0
[junit4:junit4] 2> 899667 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[38 (1435524379487240192)]} 0 3
[junit4:junit4] 2> 899669 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[39 (1435524379492483072)]} 0 0
[junit4:junit4] 2> 899673 T2923 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[39 (1435524379494580224)]} 0 1
[junit4:junit4] 2> 899673 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[39 (1435524379494580224)]} 0 2
[junit4:junit4] 2> 899675 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[40 (1435524379498774528)]} 0 0
[junit4:junit4] 2> 899681 T2938 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[40 (1435524379502968832)]} 0 1
[junit4:junit4] 2> 899681 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[40 (1435524379502968832)]} 0 2
[junit4:junit4] 2> 899681 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[40]} 0 4
[junit4:junit4] 2> 899683 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[41 (1435524379507163136)]} 0 0
[junit4:junit4] 2> 899704 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[41 (1435524379526037504)]} 0 0
[junit4:junit4] 2> 899704 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[41 (1435524379526037504)]} 0 3
[junit4:junit4] 2> 899705 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[41]} 0 20
[junit4:junit4] 2> 899707 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[42 (1435524379532328960)]} 0 1
[junit4:junit4] 2> 899712 T2941 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[42 (1435524379535474688)]} 0 0
[junit4:junit4] 2> 899713 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[42 (1435524379535474688)]} 0 3
[junit4:junit4] 2> 899713 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[42]} 0 4
[junit4:junit4] 2> 899715 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[43 (1435524379540717568)]} 0 0
[junit4:junit4] 2> 899719 T2942 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[43 (1435524379542814720)]} 0 0
[junit4:junit4] 2> 899720 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[43 (1435524379542814720)]} 0 3
[junit4:junit4] 2> 899722 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[44 (1435524379548057600)]} 0 1
[junit4:junit4] 2> 899726 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[44 (1435524379550154752)]} 0 0
[junit4:junit4] 2> 899726 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[44 (1435524379550154752)]} 0 2
[junit4:junit4] 2> 899728 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[45 (1435524379554349056)]} 0 0
[junit4:junit4] 2> 899732 T2922 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[45 (1435524379556446208)]} 0 0
[junit4:junit4] 2> 899733 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[45 (1435524379556446208)]} 0 3
[junit4:junit4] 2> 899735 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[46 (1435524379561689088)]} 0 0
[junit4:junit4] 2> 899740 T2941 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[46 (1435524379564834816)]} 0 0
[junit4:junit4] 2> 899741 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[46 (1435524379564834816)]} 0 3
[junit4:junit4] 2> 899741 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[46]} 0 4
[junit4:junit4] 2> 899743 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[47 (1435524379570077696)]} 0 0
[junit4:junit4] 2> 899749 T2938 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[47 (1435524379574272000)]} 0 0
[junit4:junit4] 2> 899749 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[47 (1435524379574272000)]} 0 2
[junit4:junit4] 2> 899750 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[47]} 0 5
[junit4:junit4] 2> 899753 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[48 (1435524379580563456)]} 0 0
[junit4:junit4] 2> 899757 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[48 (1435524379582660608)]} 0 0
[junit4:junit4] 2> 899758 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[48 (1435524379582660608)]} 0 3
[junit4:junit4] 2> 899759 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[49 (1435524379586854912)]} 0 0
[junit4:junit4] 2> 899765 T2942 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[49 (1435524379591049216)]} 0 0
[junit4:junit4] 2> 899765 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[49 (1435524379591049216)]} 0 2
[junit4:junit4] 2> 899766 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[49]} 0 5
[junit4:junit4] 2> 899768 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[50 (1435524379596292096)]} 0 0
[junit4:junit4] 2> 899773 T2941 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[50 (1435524379599437824)]} 0 0
[junit4:junit4] 2> 899774 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[50 (1435524379599437824)]} 0 3
[junit4:junit4] 2> 899775 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[50]} 0 5
[junit4:junit4] 2> 899777 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[51 (1435524379605729280)]} 0 0
[junit4:junit4] 2> 899781 T2938 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[51 (1435524379607826432)]} 0 0
[junit4:junit4] 2> 899781 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[51 (1435524379607826432)]} 0 2
[junit4:junit4] 2> 899784 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[52 (1435524379613069312)]} 0 1
[junit4:junit4] 2> 899790 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[52 (1435524379617263616)]} 0 0
[junit4:junit4] 2> 899791 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[52 (1435524379617263616)]} 0 3
[junit4:junit4] 2> 899791 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[52]} 0 5
[junit4:junit4] 2> 899793 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[53 (1435524379622506496)]} 0 0
[junit4:junit4] 2> 899797 T2924 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[53 (1435524379624603648)]} 0 0
[junit4:junit4] 2> 899798 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[53 (1435524379624603648)]} 0 3
[junit4:junit4] 2> 899800 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[54 (1435524379629846528)]} 0 0
[junit4:junit4] 2> 899806 T2942 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[54 (1435524379634040832)]} 0 1
[junit4:junit4] 2> 899806 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[54 (1435524379634040832)]} 0 3
[junit4:junit4] 2> 899806 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[54]} 0 4
[junit4:junit4] 2> 899809 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[55 (1435524379638235136)]} 0 1
[junit4:junit4] 2> 899814 T2941 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[55 (1435524379642429440)]} 0 0
[junit4:junit4] 2> 899814 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[55 (1435524379642429440)]} 0 2
[junit4:junit4] 2> 899815 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[55]} 0 5
[junit4:junit4] 2> 899817 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[56 (1435524379647672320)]} 0 0
[junit4:junit4] 2> 899821 T2923 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[56 (1435524379649769472)]} 0 0
[junit4:junit4] 2> 899822 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[56 (1435524379649769472)]} 0 3
[junit4:junit4] 2> 899824 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[57 (1435524379655012352)]} 0 1
[junit4:junit4] 2> 899828 T2922 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[57 (1435524379657109504)]} 0 0
[junit4:junit4] 2> 899828 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[57 (1435524379657109504)]} 0 3
[junit4:junit4] 2> 899831 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[58 (1435524379661303808)]} 0 1
[junit4:junit4] 2> 899835 T2925 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[58 (1435524379664449536)]} 0 1
[junit4:junit4] 2> 899835 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[58 (1435524379664449536)]} 0 3
[junit4:junit4] 2> 899837 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[59 (1435524379668643840)]} 0 0
[junit4:junit4] 2> 899843 T2938 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[59 (1435524379672838144)]} 0 1
[junit4:junit4] 2> 899843 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[59 (1435524379672838144)]} 0 2
[junit4:junit4] 2> 899844 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[59]} 0 5
[junit4:junit4] 2> 899846 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[60 (1435524379678081024)]} 0 0
[junit4:junit4] 2> 899852 T2924 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[60 (1435524379682275328)]} 0 1
[junit4:junit4] 2> 899852 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[60 (1435524379682275328)]} 0 3
[junit4:junit4] 2> 899853 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[60]} 0 5
[junit4:junit4] 2> 899855 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[61 (1435524379686469632)]} 0 1
[junit4:junit4] 2> 899859 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[61 (1435524379689615360)]} 0 0
[junit4:junit4] 2> 899859 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[61 (1435524379689615360)]} 0 2
[junit4:junit4] 2> 899862 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[62 (1435524379693809664)]} 0 1
[junit4:junit4] 2> 899868 T2923 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[62 (1435524379698003968)]} 0 1
[junit4:junit4] 2> 899868 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[62 (1435524379698003968)]} 0 3
[junit4:junit4] 2> 899869 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[62]} 0 6
[junit4:junit4] 2> 899871 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[63 (1435524379704295424)]} 0 1
[junit4:junit4] 2> 899875 T2942 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[63 (1435524379706392576)]} 0 1
[junit4:junit4] 2> 899875 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[63 (1435524379706392576)]} 0 2
[junit4:junit4] 2> 899877 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[64 (1435524379710586880)]} 0 0
[junit4:junit4] 2> 899884 T2941 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[64 (1435524379714781184)]} 0 1
[junit4:junit4] 2> 899884 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[64 (1435524379714781184)]} 0 3
[junit4:junit4] 2> 899884 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[64]} 0 5
[junit4:junit4] 2> 899887 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[65 (1435524379720024064)]} 0 1
[junit4:junit4] 2> 899893 T2938 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[65 (1435524379724218368)]} 0 1
[junit4:junit4] 2> 899893 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[65 (1435524379724218368)]} 0 3
[junit4:junit4] 2> 899894 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[65]} 0 6
[junit4:junit4] 2> 899896 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[66 (1435524379730509824)]} 0 0
[junit4:junit4] 2> 899902 T2940 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[66 (1435524379734704128)]} 0 1
[junit4:junit4] 2> 899902 T2909 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[66 (1435524379734704128)]} 0 3
[junit4:junit4] 2> 899903 T2891 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[66]} 0 5
[junit4:junit4] 2> 899905 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[67 (1435524379739947008)]} 0 0
[junit4:junit4] 2> 899911 T2922 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[67 (1435524379744141312)]} 0 0
[junit4:junit4] 2> 899912 T2890 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[67 (1435524379744141312)]} 0 3
[junit4:junit4] 2> 899912 T2907 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[67]} 0 5
[junit4:junit4] 2> 899915 T2872 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[68 (1435524379749384192)]} 0 1
[junit4:junit4] 2> 899921 T2925 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[68 (1435524379754627072)]} 0 1
[junit4:junit4] 2> 899921 T2893 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=TOLEADER&wt=javabin} {add=[68 (1435524379754627072)]} 0 3
[junit4:junit4] 2> 899921 T2908 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[68]} 0 4
[junit4:junit4] 2> 899924 T2870 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[69 (1435524379758821376)]} 0 1
[junit4:junit4] 2> 899928 T2924 C240 P34281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:41567/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[69 (1435524379761967104)]} 0 0
[junit4:junit4] 2> 899929 T2892 C242 P41567 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[69 (1435524379761967104)]} 0 3
[junit4:junit4] 2> 899931 T2871 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[70 (1435524379767209984)]} 0 0
[junit4:junit4] 2> 899936 T2942 C241 P35434 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&distrib.from=http://127.0.0.1:51762/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[70 (1435524379769307136)]} 0 1
[junit4:junit4] 2> 899936 T2906 C243 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[70 (1435524379769307136)]} 0 3
[junit4:junit4] 2> 899939 T2873 C244 P34325 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[71 (1435524379775598592)]} 0 1
[junit4:jun
[...truncated too long message...]
olr.core.SolrCore@1db39014
[junit4:junit4] 2> 1033305 T2855 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=686,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 1033306 T2855 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1033306 T2855 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1033307 T2855 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 1033309 T2855 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1033309 T2855 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1033310 T2855 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4;done=false>>]
[junit4:junit4] 2> 1033310 T2855 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4
[junit4:junit4] 2> 1033311 T2855 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/index;done=false>>]
[junit4:junit4] 2> 1033311 T2855 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148/jetty4/index
[junit4:junit4] 2> 1033312 T2977 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89720272004710412-127.0.0.1:35434_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 1033339 T2855 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 1033397 T2855 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1033399 T2855 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:43106 43106
[junit4:junit4] 2> 1033402 T2855 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 34325
[junit4:junit4] 2> !!!! WARNING: best effort to remove /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369022705148 FAILED !!!!!
[junit4:junit4] 2> 1033403 T2855 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1033403 T2855 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:43106 43106
[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=C25C22A2231AB3E4 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_MX -Dtests.timezone=Asia/Jakarta -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 160s J1 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard2 is not consistent. Got 49 from http://127.0.0.1:41567/collection1lastClient and got 48 from http://127.0.0.1:34281/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([C25C22A2231AB3E4:43BAACBA5445D3D8]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:110)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> 1033419 T2855 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 159908 T2854 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 1033516 T2929 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1033516 T2929 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> 1033516 T2929 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1034615 T2946 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1034616 T2946 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> 1034616 T2946 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=es_MX, timezone=Asia/Jakarta
[junit4:junit4] 2> NOTE: Linux 3.2.0-41-generic amd64/Oracle Corporation 1.8.0-ea (64-bit)/cpus=8,threads=4,free=29512336,total=221192192
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestPostingsSolrHighlighter, TestUtils, TestWordDelimiterFilterFactory, TestReload, SimplePostToolTest, PathHierarchyTokenizerFactoryTest, TimeZoneUtilsTest, HardAutoCommitTest, TestAnalyzedSuggestions, TestIndexingPerformance, TestFastOutputStream, TestSuggestSpellingConverter, SuggesterWFSTTest, TestSolrQueryParserDefaultOperatorResource, NotRequiredUniqueKeyTest, DirectSolrSpellCheckerTest, TestDistributedSearch, TestCSVLoader, HighlighterConfigTest, BasicDistributedZk2Test, TestUniqueKeyFieldResource, SuggesterTSTTest, TestCSVResponseWriter, SortByFunctionTest, TestElisionMultitermQuery, StandardRequestHandlerTest, TestDynamicFieldCollectionResource, TestFoldingMultitermQuery, TestSchemaNameResource, TestSolrJ, DistanceFunctionTest, TestAtomicUpdateErrorCases, ZkNodePropsTest, ShardSplitTest, TermVectorComponentDistributedTest, TestLMJelinekMercerSimilarityFactory, BasicZkTest, SignatureUpdateProcessorFactoryTest, ShardRoutingCustomTest, JSONWriterTest, NumericFieldsTest, XsltUpdateRequestHandlerTest, TestDefaultSearchFieldResource, TestZkChroot, SolrCmdDistributorTest, TestOmitPositions, CurrencyFieldXmlFileTest, TestCoreDiscovery, ZkSolrClientTest, RequiredFieldsTest, TestUpdate, TestBM25SimilarityFactory, TestSchemaResource, SolrCoreCheckLockOnStartupTest, TestQueryTypes, BadIndexSchemaTest, TestSolrQueryParserResource, SampleTest, IndexReaderFactoryTest, ConvertedLegacyTest, CurrencyFieldOpenExchangeTest, URLClassifyProcessorTest, LeaderElectionIntegrationTest, TestArbitraryIndexDir, ChaosMonkeySafeLeaderTest, TestRangeQuery, FieldAnalysisRequestHandlerTest, SpellCheckCollatorTest, TestStressLucene, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest, OpenCloseCoreStressTest, FullSolrCloudDistribCmdsTest, TestRandomFaceting, TestDistributedGrouping, TestRecovery, ZkControllerTest, TestRealTimeGet, TestJoin, TestSort, TestFunctionQuery, TestLazyCores, DirectUpdateHandlerTest, TestBadConfig, OverseerCollectionProcessorTest, TestIndexSearcher, HighlighterTest, ShowFileRequestHandlerTest, SolrRequestParserTest, SuggesterTest, SpatialFilterTest, PolyFieldTest, NoCacheHeaderTest, SchemaVersionSpecificBehaviorTest, TestPseudoReturnFields, DirectUpdateHandlerOptimizeTest, DocValuesMultiTest, SolrInfoMBeanTest, DebugComponentTest, LukeRequestHandlerTest, PrimitiveFieldTypeTest, XmlUpdateRequestHandlerTest, RequestHandlersTest, TermVectorComponentTest, IndexSchemaRuntimeFieldTest, RegexBoostProcessorTest, TestJmxIntegration, TestCollationField, JsonLoaderTest, TestPHPSerializedResponseWriter, CSVRequestHandlerTest, CoreContainerCoreInitFailuresTest, TestBinaryResponseWriter, UpdateParamsTest, TestQuerySenderNoQuery, ResponseLogComponentTest, BadComponentTest, TestMergePolicyConfig, MultiTermTest, TestBinaryField, OutputWriterTest, TestSolrCoreProperties, TestLuceneMatchVersion, TestCodecSupport, SynonymTokenizerTest, TestSweetSpotSimilarityFactory, TestDFRSimilarityFactory, TestLMDirichletSimilarityFactory, LegacyHTMLStripCharFilterTest, OpenExchangeRatesOrgProviderTest, PluginInfoTest, DateMathParserTest, TestSystemIdResolver, DOMUtilTest, ClusterStateTest, TestLRUCache, FileUtilsTest, SolrTestCaseJ4Test, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 161.19s, 1 test, 1 failure <<< FAILURES!
[...truncated 10 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:377: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:357: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1240: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:884: There were test failures: 295 suites, 1231 tests, 1 failure, 16 ignored (7 assumptions)
Total time: 34 minutes 48 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.8.0-ea-b89 -XX:+UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure