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/30 03:28:05 UTC
[JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.8.0-ea-b91) - Build #
5830 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5830/
Java: 64bit/jdk1.8.0-ea-b91 -XX:-UseCompressedOops -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
shard2 is not consistent. Got 45 from http://127.0.0.1:44623/collection1lastClient and got 44 from http://127.0.0.1:52548/collection1
Stack Trace:
java.lang.AssertionError: shard2 is not consistent. Got 45 from http://127.0.0.1:44623/collection1lastClient and got 44 from http://127.0.0.1:52548/collection1
at __randomizedtesting.SeedInfo.seed([8B968617159C1F38:A70080F62C37F04]: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 9656 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 487237 T1217 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 487249 T1217 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeyShardSplitTest-1369876701114
[junit4:junit4] 2> 487251 T1217 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 487252 T1218 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 487353 T1217 oasc.ZkTestServer.run start zk server on port:42906
[junit4:junit4] 2> 487355 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 487471 T1224 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1df7ba4d name:ZooKeeperConnection Watcher:127.0.0.1:42906 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 487471 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 487472 T1217 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 487485 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 487485 T1226 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13305783 name:ZooKeeperConnection Watcher:127.0.0.1:42906/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 487486 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 487486 T1217 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 487490 T1217 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 487493 T1217 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 487494 T1217 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 487496 T1217 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 487496 T1217 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 487500 T1217 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 487501 T1217 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 487504 T1217 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 487506 T1217 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 487511 T1217 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 487512 T1217 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 487522 T1217 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 487523 T1217 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 487533 T1217 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 487534 T1217 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 487537 T1217 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 487538 T1217 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 487542 T1217 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 487543 T1217 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 487547 T1217 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 487548 T1217 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 487682 T1217 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 487687 T1217 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59586
[junit4:junit4] 2> 487687 T1217 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 487688 T1217 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 487688 T1217 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369876701420
[junit4:junit4] 2> 487689 T1217 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369876701420/solr.xml
[junit4:junit4] 2> 487693 T1217 oasc.CoreContainer.<init> New CoreContainer 184209037
[junit4:junit4] 2> 487694 T1217 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369876701420/'
[junit4:junit4] 2> 487695 T1217 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369876701420/'
[junit4:junit4] 2> 487780 T1217 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 487781 T1217 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 487781 T1217 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 487782 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 487783 T1217 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 487783 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 487784 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 487784 T1217 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 487784 T1217 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 487785 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 487791 T1217 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 487792 T1217 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42906/solr
[junit4:junit4] 2> 487792 T1217 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 487794 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 487795 T1237 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@309d2504 name:ZooKeeperConnection Watcher:127.0.0.1:42906 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 487796 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 487798 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 487807 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 487810 T1239 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12fca70c name:ZooKeeperConnection Watcher:127.0.0.1:42906/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 487810 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 487814 T1217 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 487819 T1217 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 487827 T1217 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 487832 T1217 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59586_
[junit4:junit4] 2> 487836 T1217 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59586_
[junit4:junit4] 2> 487843 T1217 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 487862 T1217 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 487865 T1217 oasc.Overseer.start Overseer (id=89776239484469251-127.0.0.1:59586_-n_0000000000) starting
[junit4:junit4] 2> 487867 T1217 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 487870 T1241 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 487871 T1217 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 487873 T1217 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 487874 T1217 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 487876 T1240 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 487879 T1242 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369876701420/collection1
[junit4:junit4] 2> 487879 T1242 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 487880 T1242 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 487880 T1242 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 487881 T1242 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369876701420/collection1/'
[junit4:junit4] 2> 487881 T1242 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369876701420/collection1/lib/README' to classloader
[junit4:junit4] 2> 487882 T1242 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369876701420/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 487950 T1242 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 488014 T1242 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 488017 T1242 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 488026 T1242 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 488515 T1242 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 488519 T1242 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 488521 T1242 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 488528 T1242 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 488576 T1242 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 488577 T1242 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369876701420/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/control/data/
[junit4:junit4] 2> 488577 T1242 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@551d1184
[junit4:junit4] 2> 488577 T1242 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 488578 T1242 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/control/data
[junit4:junit4] 2> 488578 T1242 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/control/data/index/
[junit4:junit4] 2> 488579 T1242 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 488579 T1242 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/control/data/index
[junit4:junit4] 2> 488583 T1242 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5535fc lockFactory=org.apache.lucene.store.NativeFSLockFactory@3186aeaf),segFN=segments_1,generation=1}
[junit4:junit4] 2> 488583 T1242 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 488588 T1242 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 488589 T1242 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 488590 T1242 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 488591 T1242 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 488593 T1242 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 488594 T1242 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 488594 T1242 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 488595 T1242 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 488595 T1242 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 488597 T1242 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 488602 T1242 oass.SolrIndexSearcher.<init> Opening Searcher@696d2d47 main
[junit4:junit4] 2> 488603 T1242 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/control/data/tlog
[junit4:junit4] 2> 488603 T1242 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 488604 T1242 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 488609 T1242 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 488610 T1242 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 488610 T1243 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@696d2d47 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 489380 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 489381 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59586",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59586_"}
[junit4:junit4] 2> 489381 T1240 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 489382 T1240 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 489387 T1239 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> 489613 T1242 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 489614 T1242 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59586 collection:control_collection shard:shard1
[junit4:junit4] 2> 489615 T1242 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 489623 T1242 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 489626 T1242 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 489626 T1242 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 489626 T1242 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59586/collection1/
[junit4:junit4] 2> 489627 T1242 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 489627 T1242 oasc.SyncStrategy.syncToMe http://127.0.0.1:59586/collection1/ has no replicas
[junit4:junit4] 2> 489627 T1242 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59586/collection1/
[junit4:junit4] 2> 489627 T1242 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 490893 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 490902 T1239 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> 490937 T1242 oasc.ZkController.register We are http://127.0.0.1:59586/collection1/ and leader is http://127.0.0.1:59586/collection1/
[junit4:junit4] 2> 490937 T1242 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59586
[junit4:junit4] 2> 490937 T1242 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 490938 T1242 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 490938 T1242 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 490940 T1242 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 490954 T1217 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 490954 T1217 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 490955 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 490960 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 490963 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 490964 T1246 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a325c6d name:ZooKeeperConnection Watcher:127.0.0.1:42906/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 490964 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 490966 T1217 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 490968 T1217 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 491083 T1217 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 491111 T1217 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:44623
[junit4:junit4] 2> 491114 T1217 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 491114 T1217 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 491115 T1217 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369876704832
[junit4:junit4] 2> 491115 T1217 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369876704832/solr.xml
[junit4:junit4] 2> 491115 T1217 oasc.CoreContainer.<init> New CoreContainer 1598379245
[junit4:junit4] 2> 491116 T1217 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369876704832/'
[junit4:junit4] 2> 491116 T1217 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369876704832/'
[junit4:junit4] 2> 491212 T1217 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 491212 T1217 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 491213 T1217 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 491213 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 491214 T1217 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 491214 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 491214 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 491215 T1217 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 491215 T1217 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 491215 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 491222 T1217 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 491222 T1217 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42906/solr
[junit4:junit4] 2> 491223 T1217 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 491223 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 491227 T1257 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6e224d5a name:ZooKeeperConnection Watcher:127.0.0.1:42906 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 491229 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 491231 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 491236 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 491240 T1259 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@35ea0a02 name:ZooKeeperConnection Watcher:127.0.0.1:42906/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 491241 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 491250 T1217 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 492255 T1217 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44623_
[junit4:junit4] 2> 492256 T1217 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44623_
[junit4:junit4] 2> 492260 T1239 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 492260 T1246 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 492260 T1239 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> 492260 T1259 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 492267 T1260 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369876704832/collection1
[junit4:junit4] 2> 492267 T1260 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 492269 T1260 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 492270 T1260 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 492271 T1260 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369876704832/collection1/'
[junit4:junit4] 2> 492272 T1260 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369876704832/collection1/lib/README' to classloader
[junit4:junit4] 2> 492273 T1260 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369876704832/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 492312 T1260 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 492366 T1260 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 492368 T1260 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 492373 T1260 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 492412 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 492413 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59586",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59586_"}
[junit4:junit4] 2> 492418 T1246 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> 492418 T1259 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> 492418 T1239 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> 492826 T1260 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 492829 T1260 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 492831 T1260 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 492836 T1260 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 492873 T1260 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 492873 T1260 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369876704832/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty1/
[junit4:junit4] 2> 492874 T1260 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@551d1184
[junit4:junit4] 2> 492874 T1260 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 492875 T1260 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty1
[junit4:junit4] 2> 492875 T1260 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty1/index/
[junit4:junit4] 2> 492875 T1260 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 492876 T1260 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty1/index
[junit4:junit4] 2> 492879 T1260 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@718a3b1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@68c8ba7e),segFN=segments_1,generation=1}
[junit4:junit4] 2> 492879 T1260 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 492882 T1260 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 492882 T1260 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 492883 T1260 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 492884 T1260 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 492885 T1260 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 492885 T1260 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 492886 T1260 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 492887 T1260 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 492888 T1260 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 492890 T1260 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 492894 T1260 oass.SolrIndexSearcher.<init> Opening Searcher@6838b2c1 main
[junit4:junit4] 2> 492895 T1260 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty1/tlog
[junit4:junit4] 2> 492895 T1260 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 492896 T1260 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 492903 T1261 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6838b2c1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 492903 T1260 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 492906 T1260 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 493923 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 493924 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44623",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44623_"}
[junit4:junit4] 2> 493924 T1240 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 493925 T1240 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 493932 T1239 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> 493932 T1259 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> 493932 T1246 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> 494908 T1260 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 494909 T1260 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44623 collection:collection1 shard:shard2
[junit4:junit4] 2> 494909 T1260 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 494916 T1260 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 494918 T1260 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 494919 T1260 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 494919 T1260 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:44623/collection1/
[junit4:junit4] 2> 494919 T1260 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 494919 T1260 oasc.SyncStrategy.syncToMe http://127.0.0.1:44623/collection1/ has no replicas
[junit4:junit4] 2> 494919 T1260 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:44623/collection1/
[junit4:junit4] 2> 494920 T1260 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 495437 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 495443 T1246 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> 495444 T1239 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> 495444 T1259 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> 495478 T1260 oasc.ZkController.register We are http://127.0.0.1:44623/collection1/ and leader is http://127.0.0.1:44623/collection1/
[junit4:junit4] 2> 495478 T1260 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44623
[junit4:junit4] 2> 495478 T1260 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 495479 T1260 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 495479 T1260 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 495481 T1260 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 495482 T1217 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 495482 T1217 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 495482 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 495576 T1217 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 495578 T1217 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52776
[junit4:junit4] 2> 495580 T1217 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 495580 T1217 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 495581 T1217 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369876709349
[junit4:junit4] 2> 495581 T1217 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369876709349/solr.xml
[junit4:junit4] 2> 495581 T1217 oasc.CoreContainer.<init> New CoreContainer 1608312298
[junit4:junit4] 2> 495582 T1217 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369876709349/'
[junit4:junit4] 2> 495582 T1217 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369876709349/'
[junit4:junit4] 2> 495645 T1217 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 495646 T1217 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 495646 T1217 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 495646 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 495646 T1217 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 495647 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 495647 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 495647 T1217 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 495648 T1217 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 495648 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 495651 T1217 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 495652 T1217 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42906/solr
[junit4:junit4] 2> 495652 T1217 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 495653 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 495654 T1273 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@65e6119b name:ZooKeeperConnection Watcher:127.0.0.1:42906 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 495655 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 495657 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 495663 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 495666 T1275 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@55831e4 name:ZooKeeperConnection Watcher:127.0.0.1:42906/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 495667 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 495673 T1217 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 496678 T1217 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52776_
[junit4:junit4] 2> 496679 T1217 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52776_
[junit4:junit4] 2> 496682 T1246 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> 496682 T1239 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 496682 T1239 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> 496682 T1275 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 496682 T1259 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 496683 T1259 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> 496684 T1246 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 496689 T1276 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369876709349/collection1
[junit4:junit4] 2> 496689 T1276 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 496690 T1276 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 496690 T1276 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 496691 T1276 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369876709349/collection1/'
[junit4:junit4] 2> 496692 T1276 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369876709349/collection1/lib/README' to classloader
[junit4:junit4] 2> 496693 T1276 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369876709349/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 496730 T1276 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 496780 T1276 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 496781 T1276 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 496788 T1276 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 496955 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 496956 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44623",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:44623_"}
[junit4:junit4] 2> 496961 T1259 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> 496961 T1239 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> 496961 T1275 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> 496961 T1246 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> 497193 T1276 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 497196 T1276 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 497197 T1276 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 497201 T1276 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 497229 T1276 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 497229 T1276 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369876709349/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty2/
[junit4:junit4] 2> 497229 T1276 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@551d1184
[junit4:junit4] 2> 497230 T1276 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 497231 T1276 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty2
[junit4:junit4] 2> 497231 T1276 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty2/index/
[junit4:junit4] 2> 497231 T1276 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 497232 T1276 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty2/index
[junit4:junit4] 2> 497234 T1276 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20022caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f9639c0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 497234 T1276 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 497236 T1276 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 497236 T1276 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 497237 T1276 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 497237 T1276 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 497238 T1276 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 497238 T1276 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 497238 T1276 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 497239 T1276 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 497239 T1276 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 497240 T1276 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 497243 T1276 oass.SolrIndexSearcher.<init> Opening Searcher@63208230 main
[junit4:junit4] 2> 497243 T1276 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty2/tlog
[junit4:junit4] 2> 497244 T1276 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 497244 T1276 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 497250 T1277 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@63208230 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 497252 T1276 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 497253 T1276 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 498465 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 498467 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52776",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:52776_"}
[junit4:junit4] 2> 498467 T1240 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 498467 T1240 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 498474 T1246 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> 498474 T1239 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> 498474 T1259 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> 498474 T1275 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> 499255 T1276 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 499255 T1276 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52776 collection:collection1 shard:shard1
[junit4:junit4] 2> 499256 T1276 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 499262 T1276 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 499264 T1276 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 499265 T1276 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 499265 T1276 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52776/collection1/
[junit4:junit4] 2> 499265 T1276 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 499265 T1276 oasc.SyncStrategy.syncToMe http://127.0.0.1:52776/collection1/ has no replicas
[junit4:junit4] 2> 499266 T1276 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52776/collection1/
[junit4:junit4] 2> 499266 T1276 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 499980 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 499987 T1239 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> 499987 T1275 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> 499987 T1246 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> 499988 T1259 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> 500023 T1276 oasc.ZkController.register We are http://127.0.0.1:52776/collection1/ and leader is http://127.0.0.1:52776/collection1/
[junit4:junit4] 2> 500024 T1276 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52776
[junit4:junit4] 2> 500024 T1276 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 500024 T1276 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 500024 T1276 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 500026 T1276 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 500027 T1217 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 500028 T1217 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 500028 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 500111 T1217 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 500113 T1217 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52548
[junit4:junit4] 2> 500115 T1217 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 500115 T1217 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 500115 T1217 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369876713895
[junit4:junit4] 2> 500116 T1217 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369876713895/solr.xml
[junit4:junit4] 2> 500116 T1217 oasc.CoreContainer.<init> New CoreContainer 24397616
[junit4:junit4] 2> 500116 T1217 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369876713895/'
[junit4:junit4] 2> 500117 T1217 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369876713895/'
[junit4:junit4] 2> 500175 T1217 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 500175 T1217 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 500175 T1217 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 500176 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 500176 T1217 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 500176 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 500177 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 500177 T1217 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 500178 T1217 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 500178 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 500183 T1217 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 500183 T1217 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42906/solr
[junit4:junit4] 2> 500184 T1217 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 500185 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 500188 T1289 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c5ebb88 name:ZooKeeperConnection Watcher:127.0.0.1:42906 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 500189 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 500191 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 500199 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 500200 T1291 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5c2db2c6 name:ZooKeeperConnection Watcher:127.0.0.1:42906/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 500201 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 500205 T1217 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 501209 T1217 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52548_
[junit4:junit4] 2> 501211 T1217 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52548_
[junit4:junit4] 2> 501213 T1246 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> 501213 T1239 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 501214 T1275 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 501215 T1275 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> 501214 T1259 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> 501215 T1291 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 501214 T1239 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> 501217 T1246 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 501217 T1259 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 501220 T1292 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369876713895/collection1
[junit4:junit4] 2> 501221 T1292 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 501221 T1292 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 501222 T1292 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 501223 T1292 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369876713895/collection1/'
[junit4:junit4] 2> 501224 T1292 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369876713895/collection1/lib/README' to classloader
[junit4:junit4] 2> 501224 T1292 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369876713895/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 501253 T1292 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 501301 T1292 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 501302 T1292 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 501308 T1292 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 501493 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 501494 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52776",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52776_"}
[junit4:junit4] 2> 501500 T1291 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> 501500 T1239 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> 501500 T1259 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> 501500 T1275 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> 501500 T1246 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> 501699 T1292 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 501702 T1292 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 501704 T1292 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 501708 T1292 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 501740 T1292 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 501740 T1292 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369876713895/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty3/
[junit4:junit4] 2> 501741 T1292 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@551d1184
[junit4:junit4] 2> 501742 T1292 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 501742 T1292 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty3
[junit4:junit4] 2> 501743 T1292 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty3/index/
[junit4:junit4] 2> 501743 T1292 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 501744 T1292 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty3/index
[junit4:junit4] 2> 501747 T1292 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a55de9e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bd20371),segFN=segments_1,generation=1}
[junit4:junit4] 2> 501747 T1292 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 501750 T1292 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 501751 T1292 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 501752 T1292 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 501752 T1292 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 501753 T1292 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 501753 T1292 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 501754 T1292 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 501754 T1292 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 501755 T1292 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 501757 T1292 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 501761 T1292 oass.SolrIndexSearcher.<init> Opening Searcher@32cb09bf main
[junit4:junit4] 2> 501761 T1292 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty3/tlog
[junit4:junit4] 2> 501762 T1292 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 501762 T1292 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 501768 T1293 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@32cb09bf main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 501771 T1292 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 501771 T1292 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 503005 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 503006 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52548",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:52548_"}
[junit4:junit4] 2> 503007 T1240 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 503007 T1240 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 503012 T1275 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> 503013 T1259 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> 503013 T1291 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> 503014 T1239 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> 503014 T1246 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> 503773 T1292 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 503773 T1292 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52548 collection:collection1 shard:shard2
[junit4:junit4] 2> 503776 T1292 oasc.ZkController.register We are http://127.0.0.1:52548/collection1/ and leader is http://127.0.0.1:44623/collection1/
[junit4:junit4] 2> 503776 T1292 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52548
[junit4:junit4] 2> 503776 T1292 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 503777 T1292 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C691 name=collection1 org.apache.solr.core.SolrCore@7bff2d62 url=http://127.0.0.1:52548/collection1 node=127.0.0.1:52548_ C691_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=down, base_url=http://127.0.0.1:52548, core=collection1, node_name=127.0.0.1:52548_}
[junit4:junit4] 2> 503777 T1294 C691 P52548 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 503777 T1292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 503779 T1294 C691 P52548 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 503780 T1217 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 503781 T1217 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 503780 T1294 C691 P52548 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 503781 T1294 C691 P52548 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 503781 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 503783 T1294 C691 P52548 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 503791 T1255 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 503892 T1217 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 503894 T1217 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46566
[junit4:junit4] 2> 503896 T1217 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 503896 T1217 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 503896 T1217 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369876717649
[junit4:junit4] 2> 503897 T1217 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369876717649/solr.xml
[junit4:junit4] 2> 503897 T1217 oasc.CoreContainer.<init> New CoreContainer 1446234986
[junit4:junit4] 2> 503898 T1217 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369876717649/'
[junit4:junit4] 2> 503898 T1217 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369876717649/'
[junit4:junit4] 2> 503973 T1217 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 503974 T1217 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 503974 T1217 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 503974 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 503975 T1217 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 503975 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 503976 T1217 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 503976 T1217 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 503976 T1217 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 503977 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 503981 T1217 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 503982 T1217 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42906/solr
[junit4:junit4] 2> 503982 T1217 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 503983 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 503985 T1306 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17c8a544 name:ZooKeeperConnection Watcher:127.0.0.1:42906 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 503985 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 503987 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 503992 T1217 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 503994 T1308 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2fb41814 name:ZooKeeperConnection Watcher:127.0.0.1:42906/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 503994 T1217 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 503999 T1217 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 504522 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 504523 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52548",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:52548_"}
[junit4:junit4] 2> 504526 T1291 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> 504527 T1246 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> 504526 T1308 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> 504526 T1275 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> 504526 T1259 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> 504527 T1239 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> 504791 T1255 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 504792 T1255 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={wt=javabin&action=PREPRECOVERY&checkLive=true&coreNodeName=4&state=recovering&core=collection1&version=2&nodeName=127.0.0.1:52548_&onlyIfLeader=true} status=0 QTime=1001
[junit4:junit4] 2> 505004 T1217 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46566_
[junit4:junit4] 2> 505005 T1217 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46566_
[junit4:junit4] 2> 505007 T1259 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> 505007 T1308 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> 505008 T1239 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> 505009 T1291 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 505009 T1291 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> 505009 T1246 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> 505010 T1239 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 505010 T1259 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 505011 T1275 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> 505016 T1308 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 505019 T1246 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 505020 T1275 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 505025 T1309 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369876717649/collection1
[junit4:junit4] 2> 505025 T1309 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 505026 T1309 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 505026 T1309 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 505027 T1309 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369876717649/collection1/'
[junit4:junit4] 2> 505028 T1309 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369876717649/collection1/lib/README' to classloader
[junit4:junit4] 2> 505028 T1309 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369876717649/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 505071 T1309 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 505118 T1309 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 505120 T1309 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 505125 T1309 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 505551 T1309 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 505554 T1309 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 505555 T1309 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 505559 T1309 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 505586 T1309 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 505586 T1309 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369876717649/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/
[junit4:junit4] 2> 505587 T1309 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@551d1184
[junit4:junit4] 2> 505587 T1309 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 505588 T1309 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4
[junit4:junit4] 2> 505588 T1309 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/index/
[junit4:junit4] 2> 505588 T1309 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 505593 T1309 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/index
[junit4:junit4] 2> 505597 T1309 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@44b8cba8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@394d9bf1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 505597 T1309 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 505601 T1309 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 505602 T1309 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 505602 T1309 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 505603 T1309 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 505604 T1309 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 505604 T1309 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 505605 T1309 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 505606 T1309 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 505607 T1309 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 505609 T1309 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 505612 T1309 oass.SolrIndexSearcher.<init> Opening Searcher@ccf50d5 main
[junit4:junit4] 2> 505612 T1309 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/tlog
[junit4:junit4] 2> 505613 T1309 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 505613 T1309 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 505621 T1310 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ccf50d5 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 505623 T1309 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 505624 T1309 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 506034 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 506035 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46566",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46566_"}
[junit4:junit4] 2> 506035 T1240 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 506035 T1240 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 506039 T1308 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> 506039 T1259 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> 506039 T1291 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> 506039 T1239 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> 506039 T1275 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> 506039 T1246 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> 506626 T1309 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 506626 T1309 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46566 collection:collection1 shard:shard1
[junit4:junit4] 2> 506629 T1309 oasc.ZkController.register We are http://127.0.0.1:46566/collection1/ and leader is http://127.0.0.1:52776/collection1/
[junit4:junit4] 2> 506629 T1309 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46566
[junit4:junit4] 2> 506629 T1309 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 506630 T1309 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C692 name=collection1 org.apache.solr.core.SolrCore@c657495 url=http://127.0.0.1:46566/collection1 node=127.0.0.1:46566_ C692_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=down, base_url=http://127.0.0.1:46566, core=collection1, node_name=127.0.0.1:46566_}
[junit4:junit4] 2> 506630 T1311 C692 P46566 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 506631 T1311 C692 P46566 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 506631 T1309 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 506632 T1311 C692 P46566 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 506632 T1311 C692 P46566 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 506633 T1217 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 506633 T1217 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 506633 T1311 C692 P46566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 506634 T1217 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 506639 T1217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 506640 T1217 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 506641 T1217 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 506641 T1271 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 506642 T1217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C693 name=collection1 org.apache.solr.core.SolrCore@7bff2d62 url=http://127.0.0.1:52548/collection1 node=127.0.0.1:52548_ C693_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=recovering, base_url=http://127.0.0.1:52548, core=collection1, shard=shard2, node_name=127.0.0.1:52548_}
[junit4:junit4] 2> 506793 T1294 C693 P52548 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:44623/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 506793 T1294 C693 P52548 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52548 START replicas=[http://127.0.0.1:44623/collection1/] nUpdates=100
[junit4:junit4] 2> 506793 T1294 C693 P52548 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 506794 T1294 C693 P52548 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 506794 T1294 C693 P52548 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 506795 T1294 C693 P52548 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 506795 T1294 C693 P52548 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 506795 T1294 C693 P52548 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:44623/collection1/. core=collection1
[junit4:junit4] 2> 506795 T1294 C693 P52548 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C694 name=collection1 org.apache.solr.core.SolrCore@4a3119f5 url=http://127.0.0.1:44623/collection1 node=127.0.0.1:44623_ C694_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=active, base_url=http://127.0.0.1:44623, core=collection1, shard=shard2, node_name=127.0.0.1:44623_, leader=true}
[junit4:junit4] 2> 506800 T1255 C694 P44623 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&getVersions=100&qt=/get&version=2&distrib=false} status=0 QTime=0
[junit4:junit4] 2> 506806 T1254 C694 P44623 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 506808 T1254 C694 P44623 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@718a3b1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@68c8ba7e),segFN=segments_1,generation=1}
[junit4:junit4] 2> 506809 T1254 C694 P44623 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 506810 T1254 C694 P44623 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@718a3b1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@68c8ba7e),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@718a3b1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@68c8ba7e),segFN=segments_2,generation=2}
[junit4:junit4] 2> 506810 T1254 C694 P44623 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 506811 T1254 C694 P44623 oass.SolrIndexSearcher.<init> Opening Searcher@6815e8bc realtime
[junit4:junit4] 2> 506811 T1254 C694 P44623 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 506812 T1254 C694 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&commit=true&openSearcher=false&waitSearcher=true&version=2&commit_end_point=true&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 506813 T1294 C693 P52548 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 506813 T1294 C693 P52548 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 506817 T1255 C694 P44623 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 506817 T1255 C694 P44623 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&qt=/replication&version=2&command=indexversion} status=0 QTime=2
[junit4:junit4] 2> 506818 T1294 C693 P52548 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 506819 T1294 C693 P52548 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 506819 T1294 C693 P52548 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 506821 T1254 C694 P44623 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&qt=/replication&generation=2&version=2&command=filelist} status=0 QTime=0
[junit4:junit4] 2> 506822 T1294 C693 P52548 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 506824 T1294 C693 P52548 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty3/index.20130530021840685
[junit4:junit4] 2> 506824 T1294 C693 P52548 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@524ab6a8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7850e0cb) fullCopy=false
[junit4:junit4] 2> 506827 T1251 C694 P44623 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=filestream&qt=/replication&generation=2&file=segments_2&command=filecontent&checksum=true} status=0 QTime=1
[junit4:junit4] 2> 506828 T1294 C693 P52548 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 506829 T1294 C693 P52548 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 506830 T1294 C693 P52548 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 506831 T1294 C693 P52548 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a55de9e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bd20371),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a55de9e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bd20371),segFN=segments_2,generation=2}
[junit4:junit4] 2> 506832 T1294 C693 P52548 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 506832 T1294 C693 P52548 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 506833 T1294 C693 P52548 oass.SolrIndexSearcher.<init> Opening Searcher@7fb50cfb main
[junit4:junit4] 2> 506834 T1293 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7fb50cfb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 506835 T1294 C693 P52548 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty3/index.20130530021840685 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty3/index.20130530021840685;done=true>>]
[junit4:junit4] 2> 506835 T1294 C693 P52548 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty3/index.20130530021840685
[junit4:junit4] 2> 506835 T1294 C693 P52548 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty3/index.20130530021840685
[junit4:junit4] 2> 506835 T1294 C693 P52548 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 506836 T1294 C693 P52548 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 506836 T1294 C693 P52548 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 506836 T1294 C693 P52548 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 506838 T1294 C693 P52548 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 507545 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 507546 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46566",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:46566_"}
[junit4:junit4] 2> 507550 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52548",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:52548_"}
[junit4:junit4] 2> 507555 T1259 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> 507555 T1291 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> 507555 T1246 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> 507555 T1239 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> 507555 T1308 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> 507555 T1275 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> 507642 T1271 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 507642 T1271 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={wt=javabin&action=PREPRECOVERY&checkLive=true&coreNodeName=5&state=recovering&core=collection1&version=2&nodeName=127.0.0.1:46566_&onlyIfLeader=true} status=0 QTime=1001
[junit4:junit4] 2> 507644 T1217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 508645 T1217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C692_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=recovering, base_url=http://127.0.0.1:46566, core=collection1, shard=shard1, node_name=127.0.0.1:46566_}
[junit4:junit4] 2> 509643 T1311 C692 P46566 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52776/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 509643 T1311 C692 P46566 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46566 START replicas=[http://127.0.0.1:52776/collection1/] nUpdates=100
[junit4:junit4] 2> 509644 T1311 C692 P46566 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 509644 T1311 C692 P46566 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 509644 T1311 C692 P46566 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 509644 T1311 C692 P46566 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 509644 T1311 C692 P46566 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 509644 T1311 C692 P46566 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52776/collection1/. core=collection1
[junit4:junit4] 2> 509644 T1311 C692 P46566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 509647 T1217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C695 name=collection1 org.apache.solr.core.SolrCore@5ed668de url=http://127.0.0.1:52776/collection1 node=127.0.0.1:52776_ C695_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=active, base_url=http://127.0.0.1:52776, core=collection1, shard=shard1, node_name=127.0.0.1:52776_, leader=true}
[junit4:junit4] 2> 509661 T1271 C695 P52776 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&getVersions=100&qt=/get&version=2&distrib=false} status=0 QTime=1
[junit4:junit4] 2> 509662 T1269 C695 P52776 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 509664 T1269 C695 P52776 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20022caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f9639c0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 509664 T1269 C695 P52776 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 509665 T1269 C695 P52776 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20022caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f9639c0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20022caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f9639c0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 509665 T1269 C695 P52776 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 509666 T1269 C695 P52776 oass.SolrIndexSearcher.<init> Opening Searcher@5b9bda9 realtime
[junit4:junit4] 2> 509666 T1269 C695 P52776 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 509666 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&commit=true&openSearcher=false&waitSearcher=true&version=2&commit_end_point=true&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> ASYNC NEW_CORE C696 name=collection1 org.apache.solr.core.SolrCore@c657495 url=http://127.0.0.1:46566/collection1 node=127.0.0.1:46566_ C696_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=recovering, base_url=http://127.0.0.1:46566, core=collection1, shard=shard1, node_name=127.0.0.1:46566_}
[junit4:junit4] 2> 509668 T1311 C696 P46566 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 509668 T1311 C696 P46566 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 509670 T1271 C695 P52776 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 509670 T1271 C695 P52776 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&qt=/replication&version=2&command=indexversion} status=0 QTime=1
[junit4:junit4] 2> 509671 T1311 C696 P46566 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 509671 T1311 C696 P46566 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 509671 T1311 C696 P46566 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 509674 T1270 C695 P52776 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=javabin&qt=/replication&generation=2&version=2&command=filelist} status=0 QTime=1
[junit4:junit4] 2> 509674 T1311 C696 P46566 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 509676 T1311 C696 P46566 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/index.20130530021843538
[junit4:junit4] 2> 509676 T1311 C696 P46566 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@b830e02 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4938e99d) fullCopy=false
[junit4:junit4] 2> 509679 T1269 C695 P52776 oasc.SolrCore.execute [collection1] webapp= path=/replication params={wt=filestream&qt=/replication&generation=2&file=segments_2&command=filecontent&checksum=true} status=0 QTime=0
[junit4:junit4] 2> 509680 T1311 C696 P46566 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 509682 T1311 C696 P46566 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 509682 T1311 C696 P46566 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 509683 T1311 C696 P46566 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@44b8cba8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@394d9bf1),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@44b8cba8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@394d9bf1),segFN=segments_2,generation=2}
[junit4:junit4] 2> 509684 T1311 C696 P46566 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 509685 T1311 C696 P46566 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 509685 T1311 C696 P46566 oass.SolrIndexSearcher.<init> Opening Searcher@7946e313 main
[junit4:junit4] 2> 509686 T1310 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7946e313 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 509687 T1311 C696 P46566 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/index.20130530021843538 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/index.20130530021843538;done=true>>]
[junit4:junit4] 2> 509687 T1311 C696 P46566 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/index.20130530021843538
[junit4:junit4] 2> 509688 T1311 C696 P46566 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/index.20130530021843538
[junit4:junit4] 2> 509688 T1311 C696 P46566 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 509688 T1311 C696 P46566 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 509688 T1311 C696 P46566 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 509688 T1311 C696 P46566 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 509690 T1311 C696 P46566 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 510564 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 510565 T1240 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46566",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:46566_"}
[junit4:junit4] 2> 510572 T1291 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> 510572 T1259 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> 510572 T1239 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> 510572 T1308 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> 510572 T1246 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> 510572 T1275 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> 510649 T1217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 510650 T1217 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C697 name=collection1 org.apache.solr.core.SolrCore@7da8fa2c url=http://127.0.0.1:59586/collection1 node=127.0.0.1:59586_ C697_STATE=coll:control_collection core:collection1 props:{collection=control_collection, state=active, base_url=http://127.0.0.1:59586, core=collection1, shard=shard1, node_name=127.0.0.1:59586_, leader=true}
[junit4:junit4] 2> 510657 T1235 C697 P59586 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 510660 T1235 C697 P59586 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5535fc lockFactory=org.apache.lucene.store.NativeFSLockFactory@3186aeaf),segFN=segments_1,generation=1}
[junit4:junit4] 2> 510660 T1235 C697 P59586 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 510662 T1235 C697 P59586 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5535fc lockFactory=org.apache.lucene.store.NativeFSLockFactory@3186aeaf),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5535fc lockFactory=org.apache.lucene.store.NativeFSLockFactory@3186aeaf),segFN=segments_2,generation=2}
[junit4:junit4] 2> 510662 T1235 C697 P59586 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 510662 T1235 C697 P59586 oass.SolrIndexSearcher.<init> Opening Searcher@6e6983fb main
[junit4:junit4] 2> 510663 T1235 C697 P59586 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 510664 T1243 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6e6983fb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 510664 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&commit=true&waitSearcher=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 510669 T1268 C695 P52776 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 510671 T1268 C695 P52776 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20022caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f9639c0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20022caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f9639c0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 510671 T1268 C695 P52776 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 510672 T1268 C695 P52776 oass.SolrIndexSearcher.<init> Opening Searcher@738125bf main
[junit4:junit4] 2> 510672 T1268 C695 P52776 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 510673 T1277 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@738125bf main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 510674 T1268 C695 P52776 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:46566/collection1/, StdNode: http://127.0.0.1:44623/collection1/, StdNode: http://127.0.0.1:52548/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C696_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=active, base_url=http://127.0.0.1:46566, core=collection1, shard=shard1, node_name=127.0.0.1:46566_}
[junit4:junit4] 2> 510681 T1302 C696 P46566 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C698 name=collection1 org.apache.solr.core.SolrCore@7bff2d62 url=http://127.0.0.1:52548/collection1 node=127.0.0.1:52548_ C698_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=active, base_url=http://127.0.0.1:52548, core=collection1, shard=shard2, node_name=127.0.0.1:52548_}
[junit4:junit4] 2> 510681 T1284 C698 P52548 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 510682 T1302 C696 P46566 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@44b8cba8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@394d9bf1),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@44b8cba8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@394d9bf1),segFN=segments_3,generation=3}
[junit4:junit4] 2> 510682 T1284 C698 P52548 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a55de9e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bd20371),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a55de9e lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bd20371),segFN=segments_3,generation=3}
[junit4:junit4] 2> 510683 T1284 C698 P52548 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> ASYNC NEW_CORE C699 name=collection1 org.apache.solr.core.SolrCore@4a3119f5 url=http://127.0.0.1:44623/collection1 node=127.0.0.1:44623_ C699_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=active, base_url=http://127.0.0.1:44623, core=collection1, shard=shard2, node_name=127.0.0.1:44623_, leader=true}
[junit4:junit4] 2> 510682 T1251 C699 P44623 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 510683 T1284 C698 P52548 oass.SolrIndexSearcher.<init> Opening Searcher@457b7fd3 main
[junit4:junit4] 2> 510682 T1302 C696 P46566 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 510685 T1251 C699 P44623 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@718a3b1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@68c8ba7e),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@718a3b1b lockFactory=org.apache.lucene.store.NativeFSLockFactory@68c8ba7e),segFN=segments_3,generation=3}
[junit4:junit4] 2> 510684 T1284 C698 P52548 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 510686 T1293 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@457b7fd3 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 510686 T1251 C699 P44623 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 510685 T1302 C696 P46566 oass.SolrIndexSearcher.<init> Opening Searcher@7352843f main
[junit4:junit4] 2> 510686 T1251 C699 P44623 oass.SolrIndexSearcher.<init> Opening Searcher@35bd1712 main
[junit4:junit4] 2> 510686 T1284 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&commit=true&waitSearcher=true&version=2&commit_end_point=true&softCommit=false&expungeDeletes=false} {commit=} 0 5
[junit4:junit4] 2> 510687 T1310 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7352843f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 510687 T1251 C699 P44623 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 510687 T1302 C696 P46566 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 510688 T1261 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@35bd1712 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 510689 T1302 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&commit=true&waitSearcher=true&version=2&commit_end_point=true&softCommit=false&expungeDeletes=false} {commit=} 0 8
[junit4:junit4] 2> 510689 T1251 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&commit=true&waitSearcher=true&version=2&commit_end_point=true&softCommit=false&expungeDeletes=false} {commit=} 0 7
[junit4:junit4] 2> 510690 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&commit=true&waitSearcher=true&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4] 2> 510691 T1217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 510693 T1255 C699 P44623 oasc.SolrCore.execute [collection1] webapp= path=/select params={wt=javabin&q=*:*&tests=checkShardConsistency&version=2&distrib=false&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 510696 T1285 C698 P52548 oasc.SolrCore.execute [collection1] webapp= path=/select params={wt=javabin&q=*:*&tests=checkShardConsistency&version=2&distrib=false&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 510698 T1271 C695 P52776 oasc.SolrCore.execute [collection1] webapp= path=/select params={wt=javabin&q=*:*&tests=checkShardConsistency&version=2&distrib=false&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 510700 T1304 C696 P46566 oasc.SolrCore.execute [collection1] webapp= path=/select params={wt=javabin&q=*:*&tests=checkShardConsistency&version=2&distrib=false&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 512706 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436419858436718592)} 0 2
[junit4:junit4] 2> 512713 T1303 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&update.from=http://127.0.0.1:52776/collection1/&_version_=-1436419858441961472&version=2} {deleteByQuery=*:* (-1436419858441961472)} 0 2
[junit4:junit4] 2> 512715 T1285 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&update.from=http://127.0.0.1:44623/collection1/&_version_=-1436419858445107200&version=2} {deleteByQuery=*:* (-1436419858445107200)} 0 1
[junit4:junit4] 2> 512716 T1255 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&version=2} {deleteByQuery=*:* (-1436419858445107200)} 0 5
[junit4:junit4] 2> 512716 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436419858441961472)} 0 8
[junit4:junit4] 2> 512720 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1436419858452447232)]} 0 1
[junit4:junit4] 2> 512726 T1304 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[0 (1436419858456641536)]} 0 0
[junit4:junit4] 2> 512727 T1270 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[0 (1436419858456641536)]} 0 4
[junit4:junit4] 2> 512728 T1254 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 6
[junit4:junit4] 2> 512731 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1436419858463981568)]} 0 1
[junit4:junit4] 2> 512737 T1301 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[1 (1436419858468175872)]} 0 1
[junit4:junit4] 2> 512738 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1436419858468175872)]} 0 5
[junit4:junit4] 2> 512742 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1436419858475515904)]} 0 1
[junit4:junit4] 2> 512749 T1287 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[2 (1436419858478661632)]} 0 2
[junit4:junit4] 2> 512750 T1253 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1436419858478661632)]} 0 6
[junit4:junit4] 2> 512753 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1436419858488098816)]} 0 0
[junit4:junit4] 2> 512762 T1283 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[3 (1436419858494390272)]} 0 1
[junit4:junit4] 2> 512763 T1251 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[3 (1436419858494390272)]} 0 5
[junit4:junit4] 2> 512763 T1271 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3]} 0 7
[junit4:junit4] 2> 512766 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1436419858501730304)]} 0 0
[junit4:junit4] 2> 512772 T1302 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[4 (1436419858504876032)]} 0 1
[junit4:junit4] 2> 512773 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1436419858504876032)]} 0 4
[junit4:junit4] 2> 512776 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1436419858512216064)]} 0 1
[junit4:junit4] 2> 512783 T1284 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[5 (1436419858517458944)]} 0 0
[junit4:junit4] 2> 512784 T1255 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[5 (1436419858517458944)]} 0 4
[junit4:junit4] 2> 512785 T1270 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5]} 0 7
[junit4:junit4] 2> 512787 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1436419858523750400)]} 0 0
[junit4:junit4] 2> 512794 T1285 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[6 (1436419858528993280)]} 0 1
[junit4:junit4] 2> 512795 T1254 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[6 (1436419858528993280)]} 0 4
[junit4:junit4] 2> 512795 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6]} 0 5
[junit4:junit4] 2> 512798 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1436419858534236160)]} 0 1
[junit4:junit4] 2> 512804 T1287 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[7 (1436419858539479040)]} 0 1
[junit4:junit4] 2> 512804 T1253 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[7 (1436419858539479040)]} 0 3
[junit4:junit4] 2> 512805 T1271 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7]} 0 5
[junit4:junit4] 2> 512807 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1436419858544721920)]} 0 0
[junit4:junit4] 2> 512812 T1303 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[8 (1436419858546819072)]} 0 0
[junit4:junit4] 2> 512813 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1436419858546819072)]} 0 4
[junit4:junit4] 2> 512816 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1436419858553110528)]} 0 1
[junit4:junit4] 2> 512824 T1283 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[9 (1436419858559401984)]} 0 1
[junit4:junit4] 2> 512825 T1251 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[9 (1436419858559401984)]} 0 4
[junit4:junit4] 2> 512825 T1270 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9]} 0 6
[junit4:junit4] 2> 512828 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1436419858565693440)]} 0 1
[junit4:junit4] 2> 512832 T1304 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[10 (1436419858568839168)]} 0 0
[junit4:junit4] 2> 512833 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1436419858568839168)]} 0 3
[junit4:junit4] 2> 512835 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1436419858574082048)]} 0 0
[junit4:junit4] 2> 512840 T1301 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[11 (1436419858577227776)]} 0 0
[junit4:junit4] 2> 512841 T1271 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1436419858577227776)]} 0 3
[junit4:junit4] 2> 512843 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1436419858582470656)]} 0 0
[junit4:junit4] 2> 512848 T1302 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[12 (1436419858585616384)]} 0 0
[junit4:junit4] 2> 512849 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1436419858585616384)]} 0 3
[junit4:junit4] 2> 512852 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1436419858590859264)]} 0 1
[junit4:junit4] 2> 512856 T1303 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[13 (1436419858594004992)]} 0 0
[junit4:junit4] 2> 512857 T1270 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1436419858594004992)]} 0 3
[junit4:junit4] 2> 512859 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1436419858599247872)]} 0 0
[junit4:junit4] 2> 512866 T1304 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[14 (1436419858604490752)]} 0 1
[junit4:junit4] 2> 512866 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[14 (1436419858604490752)]} 0 3
[junit4:junit4] 2> 512867 T1255 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14]} 0 6
[junit4:junit4] 2> 512870 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1436419858609733632)]} 0 1
[junit4:junit4] 2> 512874 T1301 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[15 (1436419858612879360)]} 0 0
[junit4:junit4] 2> 512875 T1271 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1436419858612879360)]} 0 3
[junit4:junit4] 2> 512877 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1436419858618122240)]} 0 0
[junit4:junit4] 2> 512882 T1302 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[16 (1436419858621267968)]} 0 0
[junit4:junit4] 2> 512883 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1436419858621267968)]} 0 4
[junit4:junit4] 2> 512886 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1436419858627559424)]} 0 1
[junit4:junit4] 2> 512893 T1284 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[17 (1436419858632802304)]} 0 0
[junit4:junit4] 2> 512894 T1254 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[17 (1436419858632802304)]} 0 3
[junit4:junit4] 2> 512895 T1270 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17]} 0 6
[junit4:junit4] 2> 512897 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1436419858639093760)]} 0 0
[junit4:junit4] 2> 512903 T1285 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[18 (1436419858642239488)]} 0 1
[junit4:junit4] 2> 512903 T1253 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1436419858642239488)]} 0 3
[junit4:junit4] 2> 512906 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1436419858648530944)]} 0 0
[junit4:junit4] 2> 512912 T1287 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[19 (1436419858651676672)]} 0 1
[junit4:junit4] 2> 512913 T1251 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1436419858651676672)]} 0 4
[junit4:junit4] 2> 512915 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1436419858657968128)]} 0 0
[junit4:junit4] 2> 512920 T1303 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[20 (1436419858661113856)]} 0 0
[junit4:junit4] 2> 512921 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1436419858661113856)]} 0 4
[junit4:junit4] 2> 512924 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1436419858666356736)]} 0 1
[junit4:junit4] 2> 512929 T1283 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[21 (1436419858669502464)]} 0 1
[junit4:junit4] 2> 512929 T1255 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1436419858669502464)]} 0 3
[junit4:junit4] 2> 512932 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1436419858675793920)]} 0 0
[junit4:junit4] 2> 512937 T1304 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[22 (1436419858677891072)]} 0 1
[junit4:junit4] 2> 512938 T1271 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1436419858677891072)]} 0 4
[junit4:junit4] 2> 512940 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1436419858684182528)]} 0 0
[junit4:junit4] 2> 512945 T1284 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[23 (1436419858687328256)]} 0 0
[junit4:junit4] 2> 512946 T1254 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1436419858687328256)]} 0 3
[junit4:junit4] 2> 512948 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1436419858692571136)]} 0 0
[junit4:junit4] 2> 512955 T1301 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[24 (1436419858696765440)]} 0 1
[junit4:junit4] 2> 512955 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[24 (1436419858696765440)]} 0 3
[junit4:junit4] 2> 512956 T1253 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24]} 0 6
[junit4:junit4] 2> 512958 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1436419858703056896)]} 0 0
[junit4:junit4] 2> 512965 T1285 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[25 (1436419858707251200)]} 0 1
[junit4:junit4] 2> 512966 T1251 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[25 (1436419858707251200)]} 0 4
[junit4:junit4] 2> 512966 T1270 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25]} 0 6
[junit4:junit4] 2> 512969 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1436419858714591232)]} 0 0
[junit4:junit4] 2> 512974 T1287 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[26 (1436419858717736960)]} 0 0
[junit4:junit4] 2> 512975 T1255 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1436419858717736960)]} 0 4
[junit4:junit4] 2> 512978 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1436419858722979840)]} 0 1
[junit4:junit4] 2> 512982 T1302 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[27 (1436419858726125568)]} 0 0
[junit4:junit4] 2> 512983 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1436419858726125568)]} 0 3
[junit4:junit4] 2> 512986 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1436419858731368448)]} 0 1
[junit4:junit4] 2> 512993 T1303 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[28 (1436419858736611328)]} 0 1
[junit4:junit4] 2> 512993 T1271 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[28 (1436419858736611328)]} 0 3
[junit4:junit4] 2> 512994 T1254 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28]} 0 6
[junit4:junit4] 2> 512997 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1436419858742902784)]} 0 1
[junit4:junit4] 2> 513003 T1283 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[29 (1436419858748145664)]} 0 0
[junit4:junit4] 2> 513004 T1253 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1436419858748145664)]} 0 5
[junit4:junit4] 2> 513007 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1436419858754437120)]} 0 1
[junit4:junit4] 2> 513014 T1284 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[30 (1436419858758631424)]} 0 0
[junit4:junit4] 2> 513015 T1251 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[30 (1436419858758631424)]} 0 4
[junit4:junit4] 2> 513016 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30]} 0 7
[junit4:junit4] 2> 513019 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1436419858765971456)]} 0 1
[junit4:junit4] 2> 513026 T1285 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[31 (1436419858771214336)]} 0 1
[junit4:junit4] 2> 513026 T1255 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[31 (1436419858771214336)]} 0 3
[junit4:junit4] 2> 513027 T1270 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31]} 0 6
[junit4:junit4] 2> 513029 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1436419858777505792)]} 0 0
[junit4:junit4] 2> 513034 T1304 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[32 (1436419858780651520)]} 0 0
[junit4:junit4] 2> 513035 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1436419858780651520)]} 0 4
[junit4:junit4] 2> 513037 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1436419858785894400)]} 0 0
[junit4:junit4] 2> 513044 T1287 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[33 (1436419858791137280)]} 0 0
[junit4:junit4] 2> 513045 T1254 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[33 (1436419858791137280)]} 0 4
[junit4:junit4] 2> 513045 T1271 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33]} 0 6
[junit4:junit4] 2> 513048 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1436419858797428736)]} 0 1
[junit4:junit4] 2> 513054 T1301 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[34 (1436419858801623040)]} 0 0
[junit4:junit4] 2> 513055 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[34 (1436419858801623040)]} 0 3
[junit4:junit4] 2> 513056 T1253 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34]} 0 6
[junit4:junit4] 2> 513058 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1436419858807914496)]} 0 0
[junit4:junit4] 2> 513063 T1302 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[35 (1436419858811060224)]} 0 0
[junit4:junit4] 2> 513064 T1270 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1436419858811060224)]} 0 4
[junit4:junit4] 2> 513066 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1436419858816303104)]} 0 0
[junit4:junit4] 2> 513073 T1303 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[36 (1436419858821545984)]} 0 1
[junit4:junit4] 2> 513074 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[36 (1436419858821545984)]} 0 4
[junit4:junit4] 2> 513074 T1251 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36]} 0 5
[junit4:junit4] 2> 513077 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1436419858827837440)]} 0 0
[junit4:junit4] 2> 513084 T1283 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[37 (1436419858833080320)]} 0 0
[junit4:junit4] 2> 513085 T1255 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[37 (1436419858833080320)]} 0 3
[junit4:junit4] 2> 513086 T1271 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37]} 0 6
[junit4:junit4] 2> 513088 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1436419858839371776)]} 0 0
[junit4:junit4] 2> 513093 T1304 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[38 (1436419858842517504)]} 0 0
[junit4:junit4] 2> 513094 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1436419858842517504)]} 0 3
[junit4:junit4] 2> 513097 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1436419858847760384)]} 0 1
[junit4:junit4] 2> 513102 T1284 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[39 (1436419858850906112)]} 0 1
[junit4:junit4] 2> 513102 T1254 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1436419858850906112)]} 0 3
[junit4:junit4] 2> 513105 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1436419858857197568)]} 0 0
[junit4:junit4] 2> 513110 T1303 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[40 (1436419858859294720)]} 0 1
[junit4:junit4] 2> 513110 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1436419858859294720)]} 0 3
[junit4:junit4] 2> 513113 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1436419858864537600)]} 0 1
[junit4:junit4] 2> 513120 T1301 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[41 (1436419858869780480)]} 0 1
[junit4:junit4] 2> 513120 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[41 (1436419858869780480)]} 0 3
[junit4:junit4] 2> 513121 T1251 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41]} 0 6
[junit4:junit4] 2> 513124 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1436419858876071936)]} 0 1
[junit4:junit4] 2> 513130 T1304 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[42 (1436419858881314816)]} 0 1
[junit4:junit4] 2> 513130 T1270 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[42 (1436419858881314816)]} 0 3
[junit4:junit4] 2> 513131 T1255 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42]} 0 5
[junit4:junit4] 2> 513133 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1436419858886557696)]} 0 0
[junit4:junit4] 2> 513138 T1302 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[43 (1436419858889703424)]} 0 1
[junit4:junit4] 2> 513139 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1436419858889703424)]} 0 4
[junit4:junit4] 2> 513141 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1436419858894946304)]} 0 0
[junit4:junit4] 2> 513146 T1303 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[44 (1436419858897043456)]} 0 1
[junit4:junit4] 2> 513146 T1271 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1436419858897043456)]} 0 3
[junit4:junit4] 2> 513149 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1436419858903334912)]} 0 0
[junit4:junit4] 2> 513153 T1287 C698 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[45 (1436419858905432064)]} 0 0
[junit4:junit4] 2> 513154 T1253 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1436419858905432064)]} 0 3
[junit4:junit4] 2> 513157 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1436419858910674944)]} 0 1
[junit4:junit4] 2> 513164 T1301 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[46 (1436419858915917824)]} 0 1
[junit4:junit4] 2> 513165 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[46 (1436419858915917824)]} 0 4
[junit4:junit4] 2> 513165 T1254 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46]} 0 6
[junit4:junit4] 2> 513168 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1436419858923257856)]} 0 0
[junit4:junit4] 2> 513175 T1304 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[47 (1436419858928500736)]} 0 0
[junit4:junit4] 2> 513176 T1270 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[47 (1436419858928500736)]} 0 4
[junit4:junit4] 2> 513177 T1251 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47]} 0 7
[junit4:junit4] 2> 513181 T1234 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1436419858935840768)]} 0 1
[junit4:junit4] 2> 513187 T1302 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[48 (1436419858940035072)]} 0 1
[junit4:junit4] 2> 513188 T1269 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1436419858940035072)]} 0 4
[junit4:junit4] 2> 513191 T1233 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1436419858946326528)]} 0 1
[junit4:junit4] 2> 513196 T1303 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[49 (1436419858949472256)]} 0 1
[junit4:junit4] 2> 513197 T1271 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1436419858949472256)]} 0 4
[junit4:junit4] 2> 513200 T1235 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1436419858955763712)]} 0 1
[junit4:junit4] 2> 513208 T1301 C696 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[50 (1436419858962055168)]} 0 1
[junit4:junit4] 2> 513209 T1268 C695 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[50 (1436419858962055168)]} 0 4
[junit4:junit4] 2> 513209 T1255 C699 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50]} 0 7
[junit4:junit4] 2> 513212 T1232 C697 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1436419858969395200)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C700 name=collection1 org.apache.solr.core.SolrCore@c657495 url=http://127.0.0.1:46566/collection1 node=127.0.0.1:46566_ C700_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=active, base_url=http://127.0.0.1:46566, core=collection1, shard=shard1, node_name=127.0.0.1:46566_}
[junit4:junit4] 2> 513232 T1304 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[51 (1436419858987220992)]} 0 1
[junit4:junit4] 2> ASYNC NEW_CORE C701 name=collection1 org.apache.solr.core.SolrCore@5ed668de url=http://127.0.0.1:52776/collection1 node=127.0.0.1:52776_ C701_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=active, base_url=http://127.0.0.1:52776, core=collection1, shard=shard1, node_name=127.0.0.1:52776_, leader=true}
[junit4:junit4] 2> 513233 T1270 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[51 (1436419858987220992)]} 0 16
[junit4:junit4] 2> ASYNC NEW_CORE C702 name=collection1 org.apache.solr.core.SolrCore@4a3119f5 url=http://127.0.0.1:44623/collection1 node=127.0.0.1:44623_ C702_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=active, base_url=http://127.0.0.1:44623, core=collection1, shard=shard2, node_name=127.0.0.1:44623_, leader=true}
[junit4:junit4] 2> 513234 T1253 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51]} 0 19
[junit4:junit4] 2> ASYNC NEW_CORE C703 name=collection1 org.apache.solr.core.SolrCore@7da8fa2c url=http://127.0.0.1:59586/collection1 node=127.0.0.1:59586_ C703_STATE=coll:control_collection core:collection1 props:{collection=control_collection, state=active, base_url=http://127.0.0.1:59586, core=collection1, shard=shard1, node_name=127.0.0.1:59586_, leader=true}
[junit4:junit4] 2> 513236 T1234 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1436419858994561024)]} 0 0
[junit4:junit4] 2> 513242 T1302 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[52 (1436419858997706752)]} 0 1
[junit4:junit4] 2> 513242 T1269 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1436419858997706752)]} 0 3
[junit4:junit4] 2> 513245 T1233 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1436419859003998208)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C704 name=collection1 org.apache.solr.core.SolrCore@7bff2d62 url=http://127.0.0.1:52548/collection1 node=127.0.0.1:52548_ C704_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=active, base_url=http://127.0.0.1:52548, core=collection1, shard=shard2, node_name=127.0.0.1:52548_}
[junit4:junit4] 2> 513249 T1283 C704 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[53 (1436419859006095360)]} 0 0
[junit4:junit4] 2> 513250 T1254 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1436419859006095360)]} 0 3
[junit4:junit4] 2> 513253 T1235 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1436419859011338240)]} 0 1
[junit4:junit4] 2> 513258 T1303 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[54 (1436419859014483968)]} 0 1
[junit4:junit4] 2> 513259 T1271 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1436419859014483968)]} 0 4
[junit4:junit4] 2> 513261 T1232 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1436419859020775424)]} 0 0
[junit4:junit4] 2> 513269 T1301 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[55 (1436419859026018304)]} 0 1
[junit4:junit4] 2> 513270 T1268 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[55 (1436419859026018304)]} 0 4
[junit4:junit4] 2> 513271 T1251 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55]} 0 7
[junit4:junit4] 2> 513273 T1234 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1436419859033358336)]} 0 0
[junit4:junit4] 2> 513280 T1285 C704 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[56 (1436419859038601216)]} 0 0
[junit4:junit4] 2> 513281 T1255 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[56 (1436419859038601216)]} 0 3
[junit4:junit4] 2> 513282 T1270 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56]} 0 6
[junit4:junit4] 2> 513284 T1233 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1436419859044892672)]} 0 0
[junit4:junit4] 2> 513289 T1284 C704 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[57 (1436419859046989824)]} 0 1
[junit4:junit4] 2> 513289 T1253 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1436419859046989824)]} 0 3
[junit4:junit4] 2> 513292 T1235 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1436419859052232704)]} 0 1
[junit4:junit4] 2> 513296 T1287 C704 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[58 (1436419859055378432)]} 0 0
[junit4:junit4] 2> 513297 T1254 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1436419859055378432)]} 0 3
[junit4:junit4] 2> 513299 T1232 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1436419859060621312)]} 0 0
[junit4:junit4] 2> 513304 T1304 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[59 (1436419859063767040)]} 0 1
[junit4:junit4] 2> 513304 T1269 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1436419859063767040)]} 0 3
[junit4:junit4] 2> 513307 T1234 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1436419859069009920)]} 0 0
[junit4:junit4] 2> 513312 T1283 C704 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[60 (1436419859071107072)]} 0 1
[junit4:junit4] 2> 513312 T1251 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1436419859071107072)]} 0 3
[junit4:junit4] 2> 513315 T1233 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1436419859076349952)]} 0 1
[junit4:junit4] 2> 513321 T1302 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[61 (1436419859081592832)]} 0 0
[junit4:junit4] 2> 513322 T1271 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[61 (1436419859081592832)]} 0 3
[junit4:junit4] 2> 513323 T1255 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61]} 0 6
[junit4:junit4] 2> 513325 T1235 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1436419859087884288)]} 0 0
[junit4:junit4] 2> 513331 T1285 C704 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[62 (1436419859091030016)]} 0 1
[junit4:junit4] 2> 513331 T1253 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1436419859091030016)]} 0 3
[junit4:junit4] 2> 513334 T1232 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1436419859097321472)]} 0 0
[junit4:junit4] 2> 513340 T1303 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[63 (1436419859100467200)]} 0 1
[junit4:junit4] 2> 513341 T1268 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1436419859100467200)]} 0 4
[junit4:junit4] 2> 513344 T1234 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1436419859107807232)]} 0 0
[junit4:junit4] 2> 513350 T1301 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[64 (1436419859110952960)]} 0 0
[junit4:junit4] 2> 513351 T1270 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1436419859110952960)]} 0 4
[junit4:junit4] 2> 513354 T1233 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1436419859118292992)]} 0 0
[junit4:junit4] 2> 513362 T1304 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[65 (1436419859123535872)]} 0 1
[junit4:junit4] 2> 513363 T1269 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[65 (1436419859123535872)]} 0 4
[junit4:junit4] 2> 513363 T1254 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65]} 0 6
[junit4:junit4] 2> 513366 T1235 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1436419859130875904)]} 0 0
[junit4:junit4] 2> 513372 T1302 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[66 (1436419859134021632)]} 0 0
[junit4:junit4] 2> 513373 T1271 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1436419859134021632)]} 0 4
[junit4:junit4] 2> 513376 T1232 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1436419859141361664)]} 0 0
[junit4:junit4] 2> 513382 T1284 C704 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[67 (1436419859144507392)]} 0 1
[junit4:junit4] 2> 513382 T1251 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1436419859144507392)]} 0 3
[junit4:junit4] 2> 513385 T1234 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1436419859150798848)]} 0 0
[junit4:junit4] 2> 513390 T1287 C704 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[68 (1436419859153944576)]} 0 0
[junit4:junit4] 2> 513391 T1255 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1436419859153944576)]} 0 3
[junit4:junit4] 2> 513395 T1233 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1436419859160236032)]} 0 1
[junit4:junit4] 2> 513400 T1283 C704 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[69 (1436419859164430336)]} 0 0
[junit4:junit4] 2> 513401 T1253 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1436419859164430336)]} 0 4
[junit4:junit4] 2> 513405 T1235 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1436419859170721792)]} 0 1
[junit4:junit4] 2> 513410 T1303 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[70 (1436419859173867520)]} 0 0
[junit4:junit4] 2> 513411 T1268 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1436419859173867520)]} 0 4
[junit4:junit4] 2> 513414 T1232 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71 (1436419859181207552)]} 0 0
[junit4:junit4] 2> 513422 T1285 C704 P52548 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:44623/collection1/&version=2} {add=[71 (1436419859186450432)]} 0 1
[junit4:junit4] 2> 513423 T1254 C702 P44623 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[71 (1436419859186450432)]} 0 4
[junit4:junit4] 2> 513423 T1270 C701 P52776 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71]} 0 6
[junit4:junit4] 2> 513426 T1234 C703 P59586 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1436419859193790464)]} 0 0
[junit4:junit4] 2> 513432 T1301 C700 P46566 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:52776/collection1/&version=2} {add=[72 (1436419859196936192)]} 0 1
[junit4
[...truncated too long message...]
0 T1338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52548",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:52548_"}
[junit4:junit4] 2> 689563 T1338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52548",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:52548_"}
[junit4:junit4] 2> 689566 T1308 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> 689571 T1217 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 689622 T1217 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 46566
[junit4:junit4] 2> 689622 T1217 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1446234986
[junit4:junit4] 2> 689757 T1259 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 689758 T1259 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> 689758 T1259 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 690624 T1217 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 690624 T1217 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 690626 T1217 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@c657495
[junit4:junit4] 2> 690634 T1217 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=897,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 690635 T1217 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 690635 T1217 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 690635 T1217 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 690637 T1217 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 690688 T1217 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 690688 T1217 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4;done=false>>]
[junit4:junit4] 2> 690688 T1217 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4
[junit4:junit4] 2> 690689 T1217 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/index;done=false>>]
[junit4:junit4] 2> 690689 T1217 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113/jetty4/index
[junit4:junit4] 2> 690690 T1338 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89776239484469260-127.0.0.1:46566_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 690713 T1217 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 690773 T1217 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 690775 T1217 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:42906 42906
[junit4:junit4] 2> 690842 T1217 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 59586
[junit4:junit4] 2> !!!! WARNING: best effort to remove /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369876701113 FAILED !!!!!
[junit4:junit4] 2> 690842 T1217 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 690843 T1217 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:42906 42906
[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=8B968617159C1F38 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ca -Dtests.timezone=Europe/London -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE 204s J1 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard2 is not consistent. Got 45 from http://127.0.0.1:44623/collection1lastClient and got 44 from http://127.0.0.1:52548/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([8B968617159C1F38:A70080F62C37F04]: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> 690881 T1217 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 203647 T1216 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 691991 T1308 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 691992 T1308 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> 691992 T1308 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {_version_=PostingsFormat(name=Asserting), id=PostingsFormat(name=SimpleText)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=ca, timezone=Europe/London
[junit4:junit4] 2> NOTE: Linux 3.2.0-44-generic amd64/Oracle Corporation 1.8.0-ea (64-bit)/cpus=8,threads=2,free=51773136,total=169689088
[junit4:junit4] 2> NOTE: All tests run in this JVM: [HighlighterTest, FullSolrCloudDistribCmdsTest, TestArbitraryIndexDir, MultiTermTest, TestCodecSupport, EchoParamsTest, NoCacheHeaderTest, TestHashPartitioner, BasicDistributedZk2Test, NotRequiredUniqueKeyTest, StandardRequestHandlerTest, HardAutoCommitTest, TestDistributedSearch, SpellCheckCollatorTest, DocumentAnalysisRequestHandlerTest, TimeZoneUtilsTest, BasicZkTest, TestQueryTypes, IndexReaderFactoryTest, TestMaxScoreQueryParser, ChaosMonkeySafeLeaderTest, SolrIndexConfigTest, CollectionsAPIDistributedZkTest, JSONWriterTest, PathHierarchyTokenizerFactoryTest, ShardSplitTest, TestSuggestSpellingConverter, TestWordDelimiterFilterFactory, TestJmxMonitoredMap, CoreContainerCoreInitFailuresTest, TestSerializedLuceneMatchVersion, TestSchemaSimilarityResource, TestCSVLoader, TestElisionMultitermQuery, ZkSolrClientTest, TestCloudManagedSchema, TestSchemaNameResource, TestQuerySenderNoQuery, OpenExchangeRatesOrgProviderTest, SpellCheckComponentTest, FileUtilsTest, CurrencyFieldXmlFileTest, TestSolrJ, CopyFieldTest, TestFieldTypeResource, PingRequestHandlerTest, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 204.99s, 1 test, 1 failure <<< FAILURES!
[...truncated 516 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:366: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:887: There were test failures: 296 suites, 1235 tests, 1 failure, 16 ignored (7 assumptions)
Total time: 36 minutes 57 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.8.0-ea-b91 -XX:-UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure