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/29 22:17:27 UTC
[JENKINS] Lucene-Solr-trunk-Linux (64bit/jdk1.7.0_21) - Build #
5890 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/5890/
Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Wrong doc count on shard1_1 expected:<419> but was:<418>
Stack Trace:
java.lang.AssertionError: Wrong doc count on shard1_1 expected:<419> but was:<418>
at __randomizedtesting.SeedInfo.seed([FDCDE5C093F55B8E:7C2B6BD8E4AA3BB2]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(ShardSplitTest.java:167)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:155)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9386 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 216054 T694 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 216059 T694 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeyShardSplitTest-1369857646674
[junit4:junit4] 2> 216060 T694 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 216060 T695 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 216160 T694 oasc.ZkTestServer.run start zk server on port:55687
[junit4:junit4] 2> 216161 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 216285 T701 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@626a3571 name:ZooKeeperConnection Watcher:127.0.0.1:55687 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 216286 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 216286 T694 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 216292 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 216292 T696 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13ef1e0e0550000, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 216296 T703 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f8e79ea name:ZooKeeperConnection Watcher:127.0.0.1:55687/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 216296 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 216296 T694 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 216299 T694 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 216302 T694 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 216304 T694 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 216305 T694 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 216306 T694 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 216309 T694 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 216309 T694 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 216312 T694 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 216312 T694 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 216314 T694 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 216315 T694 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 216317 T694 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 216317 T694 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 216319 T694 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 216320 T694 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 216322 T694 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 216322 T694 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 216324 T694 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 216324 T694 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 216327 T694 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 216327 T694 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 216389 T694 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 216393 T694 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:42102
[junit4:junit4] 2> 216394 T694 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 216394 T694 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 216394 T694 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369857646945
[junit4:junit4] 2> 216394 T694 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369857646945/solr.xml
[junit4:junit4] 2> 216395 T694 oasc.CoreContainer.<init> New CoreContainer 141590152
[junit4:junit4] 2> 216395 T694 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369857646945/'
[junit4:junit4] 2> 216395 T694 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369857646945/'
[junit4:junit4] 2> 216440 T694 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 216440 T694 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 216441 T694 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 216441 T694 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 216441 T694 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 216441 T694 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 216442 T694 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 216442 T694 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 216442 T694 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 216442 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 216450 T694 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 216451 T694 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55687/solr
[junit4:junit4] 2> 216451 T694 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 216453 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 216454 T714 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5b15b55d name:ZooKeeperConnection Watcher:127.0.0.1:55687 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 216455 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 216457 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 216460 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 216462 T716 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2e586e59 name:ZooKeeperConnection Watcher:127.0.0.1:55687/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 216462 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 216464 T694 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 216467 T694 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 216469 T694 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 216471 T694 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42102_
[junit4:junit4] 2> 216472 T694 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42102_
[junit4:junit4] 2> 216474 T694 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 216478 T694 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 216480 T694 oasc.Overseer.start Overseer (id=89774990732623875-127.0.0.1:42102_-n_0000000000) starting
[junit4:junit4] 2> 216482 T694 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 216485 T718 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 216485 T694 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 216488 T694 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 216489 T694 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 216491 T717 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 216494 T719 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369857646945/collection1
[junit4:junit4] 2> 216494 T719 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 216494 T719 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 216495 T719 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 216495 T719 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369857646945/collection1/'
[junit4:junit4] 2> 216496 T719 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369857646945/collection1/lib/README' to classloader
[junit4:junit4] 2> 216496 T719 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369857646945/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 216518 T719 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 216544 T719 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 216545 T719 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 216555 T719 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 216808 T719 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 216810 T719 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 216811 T719 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 216814 T719 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 216836 T719 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 216837 T719 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369857646945/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/control/data/
[junit4:junit4] 2> 216837 T719 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cecbb6e
[junit4:junit4] 2> 216837 T719 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 216838 T719 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/control/data
[junit4:junit4] 2> 216838 T719 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/control/data/index/
[junit4:junit4] 2> 216838 T719 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 216838 T719 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/control/data/index
[junit4:junit4] 2> 216840 T719 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7820bab2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6130c5ea),segFN=segments_1,generation=1}
[junit4:junit4] 2> 216840 T719 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 216841 T719 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 216841 T719 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 216842 T719 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 216842 T719 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 216842 T719 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 216843 T719 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 216843 T719 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 216843 T719 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 216843 T719 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 216845 T719 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 216848 T719 oass.SolrIndexSearcher.<init> Opening Searcher@66bd9933 main
[junit4:junit4] 2> 216848 T719 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/control/data/tlog
[junit4:junit4] 2> 216849 T719 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 216849 T719 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 216853 T719 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 216853 T719 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 216854 T720 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@66bd9933 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 217994 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 217995 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:42102_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42102"}
[junit4:junit4] 2> 217995 T717 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 217995 T717 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 217999 T716 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> 218855 T719 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 218856 T719 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42102 collection:control_collection shard:shard1
[junit4:junit4] 2> 218856 T719 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 218863 T719 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 218865 T719 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 218865 T719 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 218865 T719 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:42102/collection1/
[junit4:junit4] 2> 218865 T719 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 218865 T719 oasc.SyncStrategy.syncToMe http://127.0.0.1:42102/collection1/ has no replicas
[junit4:junit4] 2> 218865 T719 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:42102/collection1/
[junit4:junit4] 2> 218866 T719 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 219503 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 219509 T716 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> 219521 T719 oasc.ZkController.register We are http://127.0.0.1:42102/collection1/ and leader is http://127.0.0.1:42102/collection1/
[junit4:junit4] 2> 219522 T719 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42102
[junit4:junit4] 2> 219522 T719 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 219522 T719 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 219522 T719 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 219524 T719 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 219525 T694 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 219525 T694 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 219526 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 219531 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 219532 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 219534 T723 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ac37b08 name:ZooKeeperConnection Watcher:127.0.0.1:55687/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 219534 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 219535 T694 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 219537 T694 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 219603 T694 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 219605 T694 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:45027
[junit4:junit4] 2> 219606 T694 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 219606 T694 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 219606 T694 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369857650152
[junit4:junit4] 2> 219607 T694 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369857650152/solr.xml
[junit4:junit4] 2> 219607 T694 oasc.CoreContainer.<init> New CoreContainer 1189214283
[junit4:junit4] 2> 219607 T694 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369857650152/'
[junit4:junit4] 2> 219608 T694 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369857650152/'
[junit4:junit4] 2> 219655 T694 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 219656 T694 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 219656 T694 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 219656 T694 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 219657 T694 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 219657 T694 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 219657 T694 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 219658 T694 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 219658 T694 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 219658 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 219662 T694 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 219663 T694 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55687/solr
[junit4:junit4] 2> 219663 T694 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 219664 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 219666 T734 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7a363ea7 name:ZooKeeperConnection Watcher:127.0.0.1:55687 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 219666 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 219668 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 219671 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 219673 T736 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6e99b7e6 name:ZooKeeperConnection Watcher:127.0.0.1:55687/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 219674 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 219677 T694 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 220680 T694 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45027_
[junit4:junit4] 2> 220681 T694 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:45027_
[junit4:junit4] 2> 220684 T723 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 220685 T716 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 220685 T716 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> 220685 T736 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 220690 T737 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369857650152/collection1
[junit4:junit4] 2> 220690 T737 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 220691 T737 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 220691 T737 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 220692 T737 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369857650152/collection1/'
[junit4:junit4] 2> 220692 T737 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369857650152/collection1/lib/README' to classloader
[junit4:junit4] 2> 220693 T737 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369857650152/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 220722 T737 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 220755 T737 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 220756 T737 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 220763 T737 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 221014 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 221015 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:42102__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:42102_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42102"}
[junit4:junit4] 2> 221019 T736 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> 221019 T716 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> 221019 T723 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> 221071 T737 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 221073 T737 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 221074 T737 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 221078 T737 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 221100 T737 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 221100 T737 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369857650152/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty1/
[junit4:junit4] 2> 221100 T737 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cecbb6e
[junit4:junit4] 2> 221101 T737 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 221101 T737 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty1
[junit4:junit4] 2> 221101 T737 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty1/index/
[junit4:junit4] 2> 221101 T737 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 221102 T737 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty1/index
[junit4:junit4] 2> 221103 T737 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29f89513 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682acafb),segFN=segments_1,generation=1}
[junit4:junit4] 2> 221103 T737 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 221105 T737 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 221105 T737 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 221106 T737 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 221106 T737 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 221106 T737 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 221106 T737 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 221107 T737 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 221107 T737 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 221107 T737 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 221110 T737 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 221111 T737 oass.SolrIndexSearcher.<init> Opening Searcher@736b865d main
[junit4:junit4] 2> 221112 T737 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty1/tlog
[junit4:junit4] 2> 221112 T737 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 221112 T737 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 221116 T738 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@736b865d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 221117 T737 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 221117 T737 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 222524 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 222524 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:45027_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45027"}
[junit4:junit4] 2> 222525 T717 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 222525 T717 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 222529 T736 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> 222529 T723 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> 222529 T716 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> 223119 T737 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 223119 T737 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:45027 collection:collection1 shard:shard1
[junit4:junit4] 2> 223120 T737 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 223125 T737 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 223127 T737 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 223127 T737 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 223127 T737 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:45027/collection1/
[junit4:junit4] 2> 223128 T737 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 223128 T737 oasc.SyncStrategy.syncToMe http://127.0.0.1:45027/collection1/ has no replicas
[junit4:junit4] 2> 223128 T737 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:45027/collection1/
[junit4:junit4] 2> 223128 T737 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 224034 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 224044 T736 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> 224044 T716 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> 224044 T723 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> 224085 T737 oasc.ZkController.register We are http://127.0.0.1:45027/collection1/ and leader is http://127.0.0.1:45027/collection1/
[junit4:junit4] 2> 224085 T737 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45027
[junit4:junit4] 2> 224085 T737 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 224086 T737 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 224086 T737 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 224088 T737 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 224089 T694 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 224089 T694 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 224090 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 224157 T694 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 224159 T694 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46475
[junit4:junit4] 2> 224159 T694 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 224160 T694 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 224160 T694 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369857654708
[junit4:junit4] 2> 224160 T694 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369857654708/solr.xml
[junit4:junit4] 2> 224160 T694 oasc.CoreContainer.<init> New CoreContainer 1540643738
[junit4:junit4] 2> 224161 T694 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369857654708/'
[junit4:junit4] 2> 224161 T694 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369857654708/'
[junit4:junit4] 2> 224198 T694 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 224198 T694 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 224199 T694 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 224199 T694 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 224199 T694 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 224199 T694 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 224200 T694 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 224200 T694 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 224200 T694 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 224200 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 224204 T694 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 224204 T694 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55687/solr
[junit4:junit4] 2> 224204 T694 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 224205 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 224207 T750 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ac370b9 name:ZooKeeperConnection Watcher:127.0.0.1:55687 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 224207 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 224209 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 224212 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 224214 T752 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12ce4f64 name:ZooKeeperConnection Watcher:127.0.0.1:55687/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 224214 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 224217 T694 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 225220 T694 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46475_
[junit4:junit4] 2> 225221 T694 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46475_
[junit4:junit4] 2> 225223 T723 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 225223 T716 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 225224 T723 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> 225223 T736 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 225224 T716 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> 225224 T752 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 225224 T736 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> 225228 T753 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369857654708/collection1
[junit4:junit4] 2> 225228 T753 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 225229 T753 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 225229 T753 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 225230 T753 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369857654708/collection1/'
[junit4:junit4] 2> 225231 T753 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369857654708/collection1/lib/README' to classloader
[junit4:junit4] 2> 225231 T753 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369857654708/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 225252 T753 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 225279 T753 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 225280 T753 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 225286 T753 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 225549 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 225550 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:45027__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:45027_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45027"}
[junit4:junit4] 2> 225553 T752 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> 225553 T723 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> 225553 T736 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> 225553 T716 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> 225565 T753 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 225567 T753 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 225569 T753 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 225572 T753 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 225591 T753 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 225591 T753 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369857654708/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty2/
[junit4:junit4] 2> 225591 T753 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cecbb6e
[junit4:junit4] 2> 225592 T753 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 225592 T753 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty2
[junit4:junit4] 2> 225592 T753 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty2/index/
[junit4:junit4] 2> 225592 T753 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 225593 T753 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty2/index
[junit4:junit4] 2> 225594 T753 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5711c365 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c53c022),segFN=segments_1,generation=1}
[junit4:junit4] 2> 225594 T753 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 225596 T753 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 225596 T753 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 225597 T753 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 225597 T753 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 225598 T753 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 225598 T753 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 225598 T753 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 225598 T753 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 225599 T753 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 225601 T753 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 225603 T753 oass.SolrIndexSearcher.<init> Opening Searcher@3263cff0 main
[junit4:junit4] 2> 225603 T753 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty2/tlog
[junit4:junit4] 2> 225604 T753 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 225604 T753 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 225608 T754 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3263cff0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 225610 T753 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 225610 T753 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 227057 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 227069 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46475_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46475"}
[junit4:junit4] 2> 227069 T717 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 227070 T717 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 227074 T736 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> 227074 T723 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> 227074 T752 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> 227074 T716 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> 227611 T753 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 227611 T753 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46475 collection:collection1 shard:shard2
[junit4:junit4] 2> 227612 T753 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 227617 T753 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 227619 T753 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 227619 T753 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 227619 T753 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46475/collection1/
[junit4:junit4] 2> 227619 T753 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 227620 T753 oasc.SyncStrategy.syncToMe http://127.0.0.1:46475/collection1/ has no replicas
[junit4:junit4] 2> 227620 T753 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46475/collection1/
[junit4:junit4] 2> 227620 T753 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 228579 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 228585 T723 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> 228585 T716 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> 228585 T736 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> 228585 T752 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> 228626 T753 oasc.ZkController.register We are http://127.0.0.1:46475/collection1/ and leader is http://127.0.0.1:46475/collection1/
[junit4:junit4] 2> 228626 T753 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46475
[junit4:junit4] 2> 228626 T753 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 228626 T753 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 228627 T753 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 228665 T753 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 228666 T694 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 228666 T694 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 228667 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 228765 T694 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 228768 T694 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51762
[junit4:junit4] 2> 228768 T694 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 228768 T694 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 228769 T694 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369857659287
[junit4:junit4] 2> 228769 T694 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369857659287/solr.xml
[junit4:junit4] 2> 228769 T694 oasc.CoreContainer.<init> New CoreContainer 1721745246
[junit4:junit4] 2> 228770 T694 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369857659287/'
[junit4:junit4] 2> 228770 T694 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369857659287/'
[junit4:junit4] 2> 228806 T694 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 228806 T694 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 228807 T694 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 228807 T694 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 228807 T694 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 228807 T694 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 228808 T694 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 228808 T694 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 228808 T694 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 228808 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 228812 T694 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 228812 T694 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55687/solr
[junit4:junit4] 2> 228812 T694 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 228813 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 228816 T766 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4052f829 name:ZooKeeperConnection Watcher:127.0.0.1:55687 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 228816 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 228818 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 228821 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 228822 T768 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6e09388c name:ZooKeeperConnection Watcher:127.0.0.1:55687/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 228823 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 228827 T694 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 229829 T694 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51762_
[junit4:junit4] 2> 229831 T694 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51762_
[junit4:junit4] 2> 229833 T716 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 229833 T768 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 229833 T716 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> 229833 T736 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 229833 T723 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 229834 T723 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> 229833 T736 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> 229833 T752 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 229834 T752 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> 229838 T769 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369857659287/collection1
[junit4:junit4] 2> 229838 T769 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 229839 T769 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 229839 T769 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 229840 T769 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369857659287/collection1/'
[junit4:junit4] 2> 229840 T769 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369857659287/collection1/lib/README' to classloader
[junit4:junit4] 2> 229840 T769 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369857659287/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 229871 T769 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 229912 T769 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 229913 T769 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 229921 T769 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 230090 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 230090 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:46475__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46475_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46475"}
[junit4:junit4] 2> 230095 T768 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> 230095 T716 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> 230095 T752 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> 230095 T736 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> 230095 T723 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> 230201 T769 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 230203 T769 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 230204 T769 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 230207 T769 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 230229 T769 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 230229 T769 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369857659287/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty3/
[junit4:junit4] 2> 230229 T769 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cecbb6e
[junit4:junit4] 2> 230230 T769 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 230230 T769 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty3
[junit4:junit4] 2> 230230 T769 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty3/index/
[junit4:junit4] 2> 230231 T769 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 230231 T769 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty3/index
[junit4:junit4] 2> 230232 T769 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3cb25814 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a82f3f3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 230232 T769 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 230234 T769 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 230234 T769 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 230235 T769 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 230235 T769 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 230236 T769 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 230236 T769 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 230236 T769 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 230236 T769 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 230237 T769 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 230239 T769 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 230241 T769 oass.SolrIndexSearcher.<init> Opening Searcher@44c938b0 main
[junit4:junit4] 2> 230241 T769 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty3/tlog
[junit4:junit4] 2> 230242 T769 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 230242 T769 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 230246 T770 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@44c938b0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 230248 T769 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 230248 T769 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 231607 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 231607 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51762_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51762"}
[junit4:junit4] 2> 231608 T717 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 231608 T717 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 231612 T723 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> 231612 T768 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> 231612 T736 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> 231612 T752 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> 231612 T716 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> 232250 T769 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 232250 T769 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51762 collection:collection1 shard:shard1
[junit4:junit4] 2> 232253 T769 oasc.ZkController.register We are http://127.0.0.1:51762/collection1/ and leader is http://127.0.0.1:45027/collection1/
[junit4:junit4] 2> 232254 T769 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51762
[junit4:junit4] 2> 232254 T769 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 232254 T769 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C331 name=collection1 org.apache.solr.core.SolrCore@295fdddd url=http://127.0.0.1:51762/collection1 node=127.0.0.1:51762_ C331_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51762_, base_url=http://127.0.0.1:51762}
[junit4:junit4] 2> 232254 T771 C331 P51762 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 232254 T769 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 232255 T771 C331 P51762 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 232255 T771 C331 P51762 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 232256 T771 C331 P51762 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 232256 T694 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 232256 T694 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 232256 T771 C331 P51762 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 232257 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 232261 T729 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:51762__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 232341 T694 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 232343 T694 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57679
[junit4:junit4] 2> 232344 T694 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 232344 T694 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 232344 T694 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369857662876
[junit4:junit4] 2> 232344 T694 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369857662876/solr.xml
[junit4:junit4] 2> 232345 T694 oasc.CoreContainer.<init> New CoreContainer 1933911458
[junit4:junit4] 2> 232345 T694 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369857662876/'
[junit4:junit4] 2> 232345 T694 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369857662876/'
[junit4:junit4] 2> 232383 T694 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 232384 T694 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 232384 T694 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 232384 T694 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 232385 T694 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 232385 T694 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 232385 T694 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 232385 T694 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 232386 T694 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 232386 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 232390 T694 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 232390 T694 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55687/solr
[junit4:junit4] 2> 232390 T694 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 232391 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 232393 T783 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c391550 name:ZooKeeperConnection Watcher:127.0.0.1:55687 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 232393 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 232395 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 232400 T694 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 232402 T785 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ef2930b name:ZooKeeperConnection Watcher:127.0.0.1:55687/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 232402 T694 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 232406 T694 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 233117 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 233117 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51762__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51762_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51762"}
[junit4:junit4] 2> 233122 T723 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> 233122 T716 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> 233122 T785 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> 233122 T736 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> 233122 T752 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> 233122 T768 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> 233261 T729 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:51762__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 233262 T729 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:51762__collection1&state=recovering&nodeName=127.0.0.1:51762_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 233408 T694 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57679_
[junit4:junit4] 2> 233410 T694 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57679_
[junit4:junit4] 2> 233413 T752 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 233413 T752 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> 233413 T716 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 233413 T736 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 233413 T768 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 233414 T768 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> 233413 T723 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 233413 T716 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> 233413 T785 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 233415 T785 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> 233414 T723 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> 233413 T736 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> 233420 T786 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369857662876/collection1
[junit4:junit4] 2> 233420 T786 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 233420 T786 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 233421 T786 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 233422 T786 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369857662876/collection1/'
[junit4:junit4] 2> 233422 T786 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369857662876/collection1/lib/README' to classloader
[junit4:junit4] 2> 233422 T786 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369857662876/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 233445 T786 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 233471 T786 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 233473 T786 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 233478 T786 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 233732 T786 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 233734 T786 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 233735 T786 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 233738 T786 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 233758 T786 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 233758 T786 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369857662876/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/
[junit4:junit4] 2> 233759 T786 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cecbb6e
[junit4:junit4] 2> 233759 T786 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 233759 T786 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4
[junit4:junit4] 2> 233759 T786 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/index/
[junit4:junit4] 2> 233760 T786 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 233760 T786 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/index
[junit4:junit4] 2> 233761 T786 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538d5506 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e58febe),segFN=segments_1,generation=1}
[junit4:junit4] 2> 233762 T786 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 233763 T786 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 233763 T786 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 233764 T786 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 233764 T786 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 233764 T786 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 233765 T786 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 233765 T786 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 233765 T786 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 233765 T786 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 233767 T786 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 233769 T786 oass.SolrIndexSearcher.<init> Opening Searcher@168851f0 main
[junit4:junit4] 2> 233770 T786 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/tlog
[junit4:junit4] 2> 233770 T786 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 233770 T786 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 233773 T787 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@168851f0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 233774 T786 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 233774 T786 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 234627 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 234628 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:57679_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57679"}
[junit4:junit4] 2> 234628 T717 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 234629 T717 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 234632 T752 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> 234632 T768 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> 234632 T736 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> 234632 T716 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> 234632 T723 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> 234632 T785 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> 234776 T786 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 234776 T786 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57679 collection:collection1 shard:shard2
[junit4:junit4] 2> 234779 T786 oasc.ZkController.register We are http://127.0.0.1:57679/collection1/ and leader is http://127.0.0.1:46475/collection1/
[junit4:junit4] 2> 234780 T786 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57679
[junit4:junit4] 2> 234780 T786 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 234780 T786 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C332 name=collection1 org.apache.solr.core.SolrCore@d72d35c url=http://127.0.0.1:57679/collection1 node=127.0.0.1:57679_ C332_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:57679_, base_url=http://127.0.0.1:57679}
[junit4:junit4] 2> 234780 T788 C332 P57679 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 234780 T786 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 234781 T788 C332 P57679 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 234782 T788 C332 P57679 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 234782 T788 C332 P57679 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 234782 T694 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 234783 T694 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 234783 T694 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 234783 T788 C332 P57679 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 234787 T694 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 234788 T747 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:57679__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 234788 T694 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 234788 T694 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 234789 T694 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C333 name=collection1 org.apache.solr.core.SolrCore@295fdddd url=http://127.0.0.1:51762/collection1 node=127.0.0.1:51762_ C333_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:51762_, base_url=http://127.0.0.1:51762}
[junit4:junit4] 2> 235262 T771 C333 P51762 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:45027/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 235263 T771 C333 P51762 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51762 START replicas=[http://127.0.0.1:45027/collection1/] nUpdates=100
[junit4:junit4] 2> 235263 T771 C333 P51762 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 235264 T771 C333 P51762 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 235265 T771 C333 P51762 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 235265 T771 C333 P51762 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 235265 T771 C333 P51762 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 235265 T771 C333 P51762 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:45027/collection1/. core=collection1
[junit4:junit4] 2> 235265 T771 C333 P51762 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C334 name=collection1 org.apache.solr.core.SolrCore@5dd18ac2 url=http://127.0.0.1:45027/collection1 node=127.0.0.1:45027_ C334_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:45027_, base_url=http://127.0.0.1:45027, leader=true}
[junit4:junit4] 2> 235276 T731 C334 P45027 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 235276 T730 C334 P45027 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 235328 T731 C334 P45027 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29f89513 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682acafb),segFN=segments_1,generation=1}
[junit4:junit4] 2> 235329 T731 C334 P45027 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 235330 T731 C334 P45027 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29f89513 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682acafb),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29f89513 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682acafb),segFN=segments_2,generation=2}
[junit4:junit4] 2> 235331 T731 C334 P45027 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 235331 T731 C334 P45027 oass.SolrIndexSearcher.<init> Opening Searcher@14d7a190 realtime
[junit4:junit4] 2> 235332 T731 C334 P45027 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 235332 T731 C334 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 56
[junit4:junit4] 2> 235333 T771 C333 P51762 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 235334 T771 C333 P51762 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 235336 T729 C334 P45027 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 235337 T729 C334 P45027 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 235338 T771 C333 P51762 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 235338 T771 C333 P51762 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 235338 T771 C333 P51762 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 235340 T730 C334 P45027 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 235341 T771 C333 P51762 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 235342 T771 C333 P51762 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty3/index.20130530070105956
[junit4:junit4] 2> 235342 T771 C333 P51762 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@470b47ea lockFactory=org.apache.lucene.store.NativeFSLockFactory@2ad5955a) fullCopy=false
[junit4:junit4] 2> 235345 T732 C334 P45027 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 235353 T771 C333 P51762 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 235370 T771 C333 P51762 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 235370 T771 C333 P51762 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 235371 T771 C333 P51762 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3cb25814 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a82f3f3),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3cb25814 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a82f3f3),segFN=segments_2,generation=2}
[junit4:junit4] 2> 235372 T771 C333 P51762 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 235372 T771 C333 P51762 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 235372 T771 C333 P51762 oass.SolrIndexSearcher.<init> Opening Searcher@5fe632dc main
[junit4:junit4] 2> 235373 T770 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5fe632dc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 235374 T771 C333 P51762 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty3/index.20130530070105956 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty3/index.20130530070105956;done=true>>]
[junit4:junit4] 2> 235374 T771 C333 P51762 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty3/index.20130530070105956
[junit4:junit4] 2> 235374 T771 C333 P51762 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty3/index.20130530070105956
[junit4:junit4] 2> 235374 T771 C333 P51762 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 235374 T771 C333 P51762 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 235375 T771 C333 P51762 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 235375 T771 C333 P51762 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 235376 T771 C333 P51762 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 235790 T694 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 236137 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 236138 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:57679__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:57679_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57679"}
[junit4:junit4] 2> 236141 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51762__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51762_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51762"}
[junit4:junit4] 2> 236147 T752 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> 236147 T723 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> 236147 T716 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> 236147 T768 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> 236147 T736 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> 236147 T785 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> 236788 T747 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:57679__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 236789 T747 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:57679__collection1&state=recovering&nodeName=127.0.0.1:57679_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2001
[junit4:junit4] 2> 236791 T694 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 237793 T694 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C332_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57679_, base_url=http://127.0.0.1:57679}
[junit4:junit4] 2> 238789 T788 C332 P57679 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:46475/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 238790 T788 C332 P57679 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:57679 START replicas=[http://127.0.0.1:46475/collection1/] nUpdates=100
[junit4:junit4] 2> 238791 T788 C332 P57679 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 238792 T788 C332 P57679 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 238792 T788 C332 P57679 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 238792 T788 C332 P57679 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 238792 T788 C332 P57679 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 238792 T788 C332 P57679 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:46475/collection1/. core=collection1
[junit4:junit4] 2> 238793 T788 C332 P57679 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 238795 T694 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C335 name=collection1 org.apache.solr.core.SolrCore@2f4f674f url=http://127.0.0.1:46475/collection1 node=127.0.0.1:46475_ C335_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:46475_, base_url=http://127.0.0.1:46475, leader=true}
[junit4:junit4] 2> 238804 T745 C335 P46475 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 238806 T747 C335 P46475 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 238881 T745 C335 P46475 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5711c365 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c53c022),segFN=segments_1,generation=1}
[junit4:junit4] 2> 238882 T745 C335 P46475 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 238897 T745 C335 P46475 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5711c365 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c53c022),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5711c365 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c53c022),segFN=segments_2,generation=2}
[junit4:junit4] 2> 238898 T745 C335 P46475 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 238905 T745 C335 P46475 oass.SolrIndexSearcher.<init> Opening Searcher@1d8477cc realtime
[junit4:junit4] 2> 238906 T745 C335 P46475 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 238906 T745 C335 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 102
[junit4:junit4] 2> 238907 T788 C332 P57679 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 238908 T788 C332 P57679 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 238910 T746 C335 P46475 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 238910 T746 C335 P46475 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 238911 T788 C332 P57679 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 238911 T788 C332 P57679 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 238911 T788 C332 P57679 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 238914 T747 C335 P46475 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 238920 T788 C332 P57679 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 238921 T788 C332 P57679 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/index.20130530070109535
[junit4:junit4] 2> 238922 T788 C332 P57679 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@7348abf lockFactory=org.apache.lucene.store.NativeFSLockFactory@3cbcaecf) fullCopy=false
[junit4:junit4] 2> 238925 T745 C335 P46475 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 238942 T788 C332 P57679 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 238944 T788 C332 P57679 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 238944 T788 C332 P57679 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 238946 T788 C332 P57679 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538d5506 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e58febe),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538d5506 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e58febe),segFN=segments_2,generation=2}
[junit4:junit4] 2> 238948 T788 C332 P57679 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 238948 T788 C332 P57679 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 238949 T788 C332 P57679 oass.SolrIndexSearcher.<init> Opening Searcher@65c9e8c9 main
[junit4:junit4] 2> 238950 T787 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@65c9e8c9 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 238950 T788 C332 P57679 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/index.20130530070109535 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/index.20130530070109535;done=true>>]
[junit4:junit4] 2> 238950 T788 C332 P57679 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/index.20130530070109535
[junit4:junit4] 2> 238951 T788 C332 P57679 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/index.20130530070109535
[junit4:junit4] 2> 238951 T788 C332 P57679 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 238951 T788 C332 P57679 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 238951 T788 C332 P57679 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 238951 T788 C332 P57679 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 238953 T788 C332 P57679 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 239157 T717 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 239158 T717 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:57679__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:57679_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57679"}
[junit4:junit4] 2> 239161 T768 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> 239162 T723 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> 239162 T752 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> 239162 T716 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> 239162 T736 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> 239162 T785 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> 239797 T694 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 239798 T694 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C336 name=collection1 org.apache.solr.core.SolrCore@2439d252 url=http://127.0.0.1:42102/collection1 node=127.0.0.1:42102_ C336_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:42102_, base_url=http://127.0.0.1:42102, leader=true}
[junit4:junit4] 2> 239805 T709 C336 P42102 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 239858 T709 C336 P42102 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7820bab2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6130c5ea),segFN=segments_1,generation=1}
[junit4:junit4] 2> 239859 T709 C336 P42102 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 239859 T709 C336 P42102 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7820bab2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6130c5ea),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7820bab2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6130c5ea),segFN=segments_2,generation=2}
[junit4:junit4] 2> 239860 T709 C336 P42102 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 239860 T709 C336 P42102 oass.SolrIndexSearcher.<init> Opening Searcher@72b454ef main
[junit4:junit4] 2> 239860 T709 C336 P42102 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 239861 T720 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@72b454ef main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 239861 T709 C336 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 56
[junit4:junit4] 2> 239867 T729 C334 P45027 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 239868 T729 C334 P45027 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29f89513 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682acafb),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29f89513 lockFactory=org.apache.lucene.store.NativeFSLockFactory@682acafb),segFN=segments_3,generation=3}
[junit4:junit4] 2> 239869 T729 C334 P45027 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 239869 T729 C334 P45027 oass.SolrIndexSearcher.<init> Opening Searcher@65079e28 main
[junit4:junit4] 2> 239870 T729 C334 P45027 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 239870 T738 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@65079e28 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 239871 T729 C334 P45027 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:51762/collection1/, StdNode: http://127.0.0.1:46475/collection1/, StdNode: http://127.0.0.1:57679/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 239882 T748 C335 P46475 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C337 name=collection1 org.apache.solr.core.SolrCore@2f4f674f url=http://127.0.0.1:46475/collection1 node=127.0.0.1:46475_ C337_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:46475_, base_url=http://127.0.0.1:46475, leader=true}
[junit4:junit4] 2> 239911 T748 C337 P46475 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5711c365 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c53c022),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5711c365 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c53c022),segFN=segments_3,generation=3}
[junit4:junit4] 2> 239912 T748 C337 P46475 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 239912 T748 C337 P46475 oass.SolrIndexSearcher.<init> Opening Searcher@63128123 main
[junit4:junit4] 2> 239912 T748 C337 P46475 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 239913 T754 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@63128123 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 239914 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 32
[junit4:junit4] 2> ASYNC NEW_CORE C338 name=collection1 org.apache.solr.core.SolrCore@d72d35c url=http://127.0.0.1:57679/collection1 node=127.0.0.1:57679_ C338_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57679_, base_url=http://127.0.0.1:57679}
[junit4:junit4] 2> 239915 T778 C338 P57679 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C339 name=collection1 org.apache.solr.core.SolrCore@295fdddd url=http://127.0.0.1:51762/collection1 node=127.0.0.1:51762_ C339_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51762_, base_url=http://127.0.0.1:51762}
[junit4:junit4] 2> 239916 T763 C339 P51762 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 239917 T778 C338 P57679 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538d5506 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e58febe),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@538d5506 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e58febe),segFN=segments_3,generation=3}
[junit4:junit4] 2> 239918 T778 C338 P57679 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 239918 T763 C339 P51762 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3cb25814 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a82f3f3),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3cb25814 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a82f3f3),segFN=segments_3,generation=3}
[junit4:junit4] 2> 239919 T763 C339 P51762 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 239919 T778 C338 P57679 oass.SolrIndexSearcher.<init> Opening Searcher@1d2c7d5 main
[junit4:junit4] 2> 239919 T763 C339 P51762 oass.SolrIndexSearcher.<init> Opening Searcher@54ffc7bc main
[junit4:junit4] 2> 239920 T778 C338 P57679 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 239921 T787 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d2c7d5 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 239921 T770 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@54ffc7bc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 239921 T778 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 239921 T763 C339 P51762 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 239922 T763 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> ASYNC NEW_CORE C340 name=collection1 org.apache.solr.core.SolrCore@5dd18ac2 url=http://127.0.0.1:45027/collection1 node=127.0.0.1:45027_ C340_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:45027_, base_url=http://127.0.0.1:45027, leader=true}
[junit4:junit4] 2> 239922 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 55
[junit4:junit4] 2> 239923 T694 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 239926 T732 C340 P45027 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 239929 T764 C339 P51762 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 239932 T747 C337 P46475 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 239934 T780 C338 P57679 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C341 name=collection1 org.apache.solr.core.SolrCore@2439d252 url=http://127.0.0.1:42102/collection1 node=127.0.0.1:42102_ C341_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:42102_, base_url=http://127.0.0.1:42102, leader=true}
[junit4:junit4] 2> 241938 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436399878853885952)} 0 1
[junit4:junit4] 2> 241944 T761 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436399878858080256&update.from=http://127.0.0.1:45027/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436399878858080256)} 0 1
[junit4:junit4] 2> 241946 T780 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436399878861225984&update.from=http://127.0.0.1:46475/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436399878861225984)} 0 0
[junit4:junit4] 2> 241947 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1436399878861225984)} 0 4
[junit4:junit4] 2> 241948 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436399878858080256)} 0 7
[junit4:junit4] 2> 241951 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1436399878867517440)]} 0 1
[junit4:junit4] 2> 241956 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1436399878871711744)]} 0 0
[junit4:junit4] 2> 241957 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1436399878871711744)]} 0 3
[junit4:junit4] 2> 241958 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 5
[junit4:junit4] 2> 241960 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1436399878878003200)]} 0 0
[junit4:junit4] 2> 241965 T762 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1436399878881148928)]} 0 1
[junit4:junit4] 2> 241965 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1436399878881148928)]} 0 3
[junit4:junit4] 2> 241968 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1436399878886391808)]} 0 1
[junit4:junit4] 2> 241973 T781 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1436399878888488960)]} 0 1
[junit4:junit4] 2> 241973 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1436399878888488960)]} 0 3
[junit4:junit4] 2> 241975 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1436399878893731840)]} 0 0
[junit4:junit4] 2> 241982 T779 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1436399878897926144)]} 0 1
[junit4:junit4] 2> 241982 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[3 (1436399878897926144)]} 0 3
[junit4:junit4] 2> 241983 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3]} 0 6
[junit4:junit4] 2> 241985 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1436399878904217600)]} 0 0
[junit4:junit4] 2> 241989 T763 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1436399878906314752)]} 0 0
[junit4:junit4] 2> 241990 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1436399878906314752)]} 0 3
[junit4:junit4] 2> 241992 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1436399878911557632)]} 0 0
[junit4:junit4] 2> 241998 T778 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1436399878915751936)]} 0 0
[junit4:junit4] 2> 241999 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1436399878915751936)]} 0 3
[junit4:junit4] 2> 241999 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5]} 0 5
[junit4:junit4] 2> 242002 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1436399878920994816)]} 0 1
[junit4:junit4] 2> 242012 T780 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1436399878924140544)]} 0 1
[junit4:junit4] 2> 242013 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1436399878924140544)]} 0 9
[junit4:junit4] 2> 242016 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1436399878936723456)]} 0 0
[junit4:junit4] 2> 242022 T781 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1436399878939869184)]} 0 0
[junit4:junit4] 2> 242023 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1436399878939869184)]} 0 4
[junit4:junit4] 2> 242026 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1436399878947209216)]} 0 1
[junit4:junit4] 2> 242041 T761 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1436399878952452096)]} 0 1
[junit4:junit4] 2> 242041 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1436399878952452096)]} 0 10
[junit4:junit4] 2> 242042 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8]} 0 13
[junit4:junit4] 2> 242044 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1436399878966083584)]} 0 0
[junit4:junit4] 2> 242049 T779 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1436399878969229312)]} 0 1
[junit4:junit4] 2> 242050 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1436399878969229312)]} 0 4
[junit4:junit4] 2> 242052 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1436399878974472192)]} 0 0
[junit4:junit4] 2> 242056 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1436399878976569344)]} 0 0
[junit4:junit4] 2> 242057 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1436399878976569344)]} 0 3
[junit4:junit4] 2> 242059 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1436399878981812224)]} 0 0
[junit4:junit4] 2> 242064 T762 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1436399878983909376)]} 0 0
[junit4:junit4] 2> 242064 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1436399878983909376)]} 0 3
[junit4:junit4] 2> 242067 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1436399878990200832)]} 0 1
[junit4:junit4] 2> 242073 T763 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1436399878993346560)]} 0 1
[junit4:junit4] 2> 242073 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1436399878993346560)]} 0 3
[junit4:junit4] 2> 242074 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12]} 0 5
[junit4:junit4] 2> 242076 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1436399878999638016)]} 0 0
[junit4:junit4] 2> 242082 T761 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1436399879003832320)]} 0 0
[junit4:junit4] 2> 242082 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1436399879003832320)]} 0 2
[junit4:junit4] 2> 242083 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13]} 0 5
[junit4:junit4] 2> 242085 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1436399879009075200)]} 0 0
[junit4:junit4] 2> 242089 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1436399879011172352)]} 0 0
[junit4:junit4] 2> 242090 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1436399879011172352)]} 0 3
[junit4:junit4] 2> 242092 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1436399879016415232)]} 0 0
[junit4:junit4] 2> 242098 T762 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1436399879020609536)]} 0 0
[junit4:junit4] 2> 242098 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1436399879020609536)]} 0 2
[junit4:junit4] 2> 242099 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15]} 0 5
[junit4:junit4] 2> 242101 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1436399879025852416)]} 0 0
[junit4:junit4] 2> 242107 T763 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1436399879030046720)]} 0 0
[junit4:junit4] 2> 242107 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1436399879030046720)]} 0 2
[junit4:junit4] 2> 242108 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16]} 0 5
[junit4:junit4] 2> 242110 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1436399879035289600)]} 0 0
[junit4:junit4] 2> 242114 T778 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1436399879037386752)]} 0 0
[junit4:junit4] 2> 242115 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1436399879037386752)]} 0 3
[junit4:junit4] 2> 242117 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1436399879042629632)]} 0 0
[junit4:junit4] 2> 242121 T780 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1436399879044726784)]} 0 0
[junit4:junit4] 2> 242121 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1436399879044726784)]} 0 2
[junit4:junit4] 2> 242124 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1436399879048921088)]} 0 1
[junit4:junit4] 2> 242130 T781 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1436399879053115392)]} 0 1
[junit4:junit4] 2> 242130 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1436399879053115392)]} 0 3
[junit4:junit4] 2> 242131 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19]} 0 5
[junit4:junit4] 2> 242133 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1436399879059406848)]} 0 0
[junit4:junit4] 2> 242137 T761 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1436399879061504000)]} 0 0
[junit4:junit4] 2> 242138 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1436399879061504000)]} 0 3
[junit4:junit4] 2> 242140 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1436399879066746880)]} 0 0
[junit4:junit4] 2> 242144 T779 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1436399879068844032)]} 0 0
[junit4:junit4] 2> 242145 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1436399879068844032)]} 0 3
[junit4:junit4] 2> 242147 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1436399879074086912)]} 0 0
[junit4:junit4] 2> 242152 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1436399879077232640)]} 0 0
[junit4:junit4] 2> 242152 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1436399879077232640)]} 0 2
[junit4:junit4] 2> 242155 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1436399879082475520)]} 0 1
[junit4:junit4] 2> 242159 T778 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1436399879084572672)]} 0 0
[junit4:junit4] 2> 242159 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1436399879084572672)]} 0 2
[junit4:junit4] 2> 242161 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1436399879088766976)]} 0 0
[junit4:junit4] 2> 242165 T762 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1436399879090864128)]} 0 0
[junit4:junit4] 2> 242166 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1436399879090864128)]} 0 3
[junit4:junit4] 2> 242168 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1436399879096107008)]} 0 0
[junit4:junit4] 2> 242172 T780 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1436399879098204160)]} 0 0
[junit4:junit4] 2> 242173 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1436399879098204160)]} 0 3
[junit4:junit4] 2> 242175 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1436399879103447040)]} 0 0
[junit4:junit4] 2> 242179 T781 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1436399879105544192)]} 0 0
[junit4:junit4] 2> 242180 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1436399879105544192)]} 0 3
[junit4:junit4] 2> 242182 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1436399879110787072)]} 0 0
[junit4:junit4] 2> 242186 T763 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1436399879112884224)]} 0 0
[junit4:junit4] 2> 242187 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1436399879112884224)]} 0 3
[junit4:junit4] 2> 242189 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1436399879118127104)]} 0 0
[junit4:junit4] 2> 242194 T761 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1436399879120224256)]} 0 1
[junit4:junit4] 2> 242194 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1436399879120224256)]} 0 3
[junit4:junit4] 2> 242196 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1436399879125467136)]} 0 0
[junit4:junit4] 2> 242202 T779 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1436399879129661440)]} 0 0
[junit4:junit4] 2> 242203 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1436399879129661440)]} 0 3
[junit4:junit4] 2> 242204 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29]} 0 6
[junit4:junit4] 2> 242206 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1436399879135952896)]} 0 0
[junit4:junit4] 2> 242212 T778 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1436399879140147200)]} 0 1
[junit4:junit4] 2> 242212 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1436399879140147200)]} 0 2
[junit4:junit4] 2> 242213 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30]} 0 5
[junit4:junit4] 2> 242215 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1436399879145390080)]} 0 0
[junit4:junit4] 2> 242221 T780 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1436399879149584384)]} 0 0
[junit4:junit4] 2> 242221 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[31 (1436399879149584384)]} 0 2
[junit4:junit4] 2> 242222 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31]} 0 5
[junit4:junit4] 2> 242224 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1436399879154827264)]} 0 0
[junit4:junit4] 2> 242228 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1436399879156924416)]} 0 0
[junit4:junit4] 2> 242229 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1436399879156924416)]} 0 3
[junit4:junit4] 2> 242231 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1436399879162167296)]} 0 0
[junit4:junit4] 2> 242235 T781 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1436399879164264448)]} 0 0
[junit4:junit4] 2> 242236 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1436399879164264448)]} 0 3
[junit4:junit4] 2> 242238 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1436399879169507328)]} 0 0
[junit4:junit4] 2> 242244 T762 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1436399879173701632)]} 0 0
[junit4:junit4] 2> 242245 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[34 (1436399879173701632)]} 0 3
[junit4:junit4] 2> 242246 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34]} 0 6
[junit4:junit4] 2> 242248 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1436399879179993088)]} 0 0
[junit4:junit4] 2> 242255 T763 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1436399879184187392)]} 0 1
[junit4:junit4] 2> 242255 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[35 (1436399879184187392)]} 0 3
[junit4:junit4] 2> 242256 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35]} 0 6
[junit4:junit4] 2> 242258 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1436399879190478848)]} 0 0
[junit4:junit4] 2> 242264 T761 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1436399879194673152)]} 0 0
[junit4:junit4] 2> 242265 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[36 (1436399879194673152)]} 0 3
[junit4:junit4] 2> 242265 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36]} 0 5
[junit4:junit4] 2> 242268 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1436399879200964608)]} 0 1
[junit4:junit4] 2> 242272 T779 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1436399879203061760)]} 0 0
[junit4:junit4] 2> 242273 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1436399879203061760)]} 0 3
[junit4:junit4] 2> 242275 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1436399879208304640)]} 0 0
[junit4:junit4] 2> 242279 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1436399879210401792)]} 0 0
[junit4:junit4] 2> 242280 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1436399879210401792)]} 0 3
[junit4:junit4] 2> 242282 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1436399879215644672)]} 0 0
[junit4:junit4] 2> 242286 T778 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1436399879217741824)]} 0 0
[junit4:junit4] 2> 242287 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1436399879217741824)]} 0 3
[junit4:junit4] 2> 242289 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1436399879222984704)]} 0 0
[junit4:junit4] 2> 242293 T762 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1436399879225081856)]} 0 0
[junit4:junit4] 2> 242294 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1436399879225081856)]} 0 3
[junit4:junit4] 2> 242296 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1436399879230324736)]} 0 0
[junit4:junit4] 2> 242302 T763 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1436399879234519040)]} 0 0
[junit4:junit4] 2> 242303 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[41 (1436399879234519040)]} 0 3
[junit4:junit4] 2> 242303 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41]} 0 5
[junit4:junit4] 2> 242305 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1436399879239761920)]} 0 0
[junit4:junit4] 2> 242311 T761 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1436399879243956224)]} 0 0
[junit4:junit4] 2> 242312 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[42 (1436399879243956224)]} 0 3
[junit4:junit4] 2> 242312 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42]} 0 4
[junit4:junit4] 2> 242315 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1436399879250247680)]} 0 1
[junit4:junit4] 2> 242320 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1436399879254441984)]} 0 0
[junit4:junit4] 2> 242321 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[43 (1436399879254441984)]} 0 3
[junit4:junit4] 2> 242321 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43]} 0 4
[junit4:junit4] 2> 242323 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1436399879258636288)]} 0 0
[junit4:junit4] 2> 242328 T762 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1436399879261782016)]} 0 1
[junit4:junit4] 2> 242328 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1436399879261782016)]} 0 3
[junit4:junit4] 2> 242331 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1436399879267024896)]} 0 1
[junit4:junit4] 2> 242335 T780 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1436399879269122048)]} 0 1
[junit4:junit4] 2> 242335 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1436399879269122048)]} 0 2
[junit4:junit4] 2> 242338 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1436399879273316352)]} 0 1
[junit4:junit4] 2> 242342 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1436399879276462080)]} 0 0
[junit4:junit4] 2> 242342 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1436399879276462080)]} 0 2
[junit4:junit4] 2> 242345 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1436399879280656384)]} 0 1
[junit4:junit4] 2> 242351 T763 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1436399879285899264)]} 0 1
[junit4:junit4] 2> 242351 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[47 (1436399879285899264)]} 0 2
[junit4:junit4] 2> 242352 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47]} 0 5
[junit4:junit4] 2> 242354 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1436399879291142144)]} 0 0
[junit4:junit4] 2> 242360 T762 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1436399879295336448)]} 0 0
[junit4:junit4] 2> 242360 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[48 (1436399879295336448)]} 0 2
[junit4:junit4] 2> 242361 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48]} 0 5
[junit4:junit4] 2> 242363 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1436399879300579328)]} 0 0
[junit4:junit4] 2> 242367 T761 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1436399879302676480)]} 0 0
[junit4:junit4] 2> 242368 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1436399879302676480)]} 0 3
[junit4:junit4] 2> 242370 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1436399879307919360)]} 0 0
[junit4:junit4] 2> 242377 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1436399879312113664)]} 0 1
[junit4:junit4] 2> 242377 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[50 (1436399879312113664)]} 0 3
[junit4:junit4] 2> 242378 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50]} 0 6
[junit4:junit4] 2> 242380 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1436399879318405120)]} 0 0
[junit4:junit4] 2> 242384 T763 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1436399879320502272)]} 0 0
[junit4:junit4] 2> 242385 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1436399879320502272)]} 0 3
[junit4:junit4] 2> 242387 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1436399879325745152)]} 0 0
[junit4:junit4] 2> 242392 T762 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1436399879328890880)]} 0 1
[junit4:junit4] 2> 242392 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1436399879328890880)]} 0 2
[junit4:junit4] 2> 242395 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1436399879333085184)]} 0 1
[junit4:junit4] 2> 242399 T781 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1436399879336230912)]} 0 0
[junit4:junit4] 2> 242400 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1436399879336230912)]} 0 3
[junit4:junit4] 2> 242402 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1436399879341473792)]} 0 0
[junit4:junit4] 2> 242406 T761 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1436399879343570944)]} 0 0
[junit4:junit4] 2> 242407 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1436399879343570944)]} 0 3
[junit4:junit4] 2> 242409 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1436399879348813824)]} 0 0
[junit4:junit4] 2> 242414 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1436399879350910976)]} 0 1
[junit4:junit4] 2> 242414 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1436399879350910976)]} 0 3
[junit4:junit4] 2> 242417 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1436399879356153856)]} 0 1
[junit4:junit4] 2> 242421 T778 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1436399879359299584)]} 0 1
[junit4:junit4] 2> 242421 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1436399879359299584)]} 0 2
[junit4:junit4] 2> 242423 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1436399879363493888)]} 0 0
[junit4:junit4] 2> 242429 T780 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1436399879367688192)]} 0 0
[junit4:junit4] 2> 242430 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[57 (1436399879367688192)]} 0 3
[junit4:junit4] 2> 242430 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57]} 0 5
[junit4:junit4] 2> 242433 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1436399879373979648)]} 0 0
[junit4:junit4] 2> 242439 T779 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1436399879378173952)]} 0 0
[junit4:junit4] 2> 242440 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[58 (1436399879378173952)]} 0 3
[junit4:junit4] 2> 242440 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58]} 0 5
[junit4:junit4] 2> 242443 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1436399879383416832)]} 0 1
[junit4:junit4] 2> 242447 T763 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1436399879386562560)]} 0 1
[junit4:junit4] 2> 242447 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1436399879386562560)]} 0 3
[junit4:junit4] 2> 242449 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1436399879390756864)]} 0 0
[junit4:junit4] 2> 242455 T781 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1436399879394951168)]} 0 0
[junit4:junit4] 2> 242456 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[60 (1436399879394951168)]} 0 3
[junit4:junit4] 2> 242457 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60]} 0 6
[junit4:junit4] 2> 242459 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1436399879401242624)]} 0 0
[junit4:junit4] 2> 242465 T762 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1436399879405436928)]} 0 0
[junit4:junit4] 2> 242466 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[61 (1436399879405436928)]} 0 3
[junit4:junit4] 2> 242466 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61]} 0 5
[junit4:junit4] 2> 242468 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1436399879410679808)]} 0 0
[junit4:junit4] 2> 242473 T778 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1436399879413825536)]} 0 1
[junit4:junit4] 2> 242473 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1436399879413825536)]} 0 3
[junit4:junit4] 2> 242476 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1436399879418019840)]} 0 1
[junit4:junit4] 2> 242480 T761 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1436399879421165568)]} 0 0
[junit4:junit4] 2> 242481 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1436399879421165568)]} 0 3
[junit4:junit4] 2> 242483 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1436399879426408448)]} 0 0
[junit4:junit4] 2> 242489 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1436399879430602752)]} 0 0
[junit4:junit4] 2> 242490 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[64 (1436399879430602752)]} 0 3
[junit4:junit4] 2> 242490 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64]} 0 5
[junit4:junit4] 2> 242493 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1436399879435845632)]} 0 1
[junit4:junit4] 2> 242497 T763 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1436399879438991360)]} 0 0
[junit4:junit4] 2> 242498 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1436399879438991360)]} 0 3
[junit4:junit4] 2> 242500 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1436399879444234240)]} 0 0
[junit4:junit4] 2> 242509 T762 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1436399879450525696)]} 0 1
[junit4:junit4] 2> 242509 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[66 (1436399879450525696)]} 0 3
[junit4:junit4] 2> 242510 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66]} 0 6
[junit4:junit4] 2> 242512 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1436399879456817152)]} 0 0
[junit4:junit4] 2> 242519 T780 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1436399879461011456)]} 0 1
[junit4:junit4] 2> 242519 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[67 (1436399879461011456)]} 0 3
[junit4:junit4] 2> 242520 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67]} 0 6
[junit4:junit4] 2> 242522 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1436399879467302912)]} 0 0
[junit4:junit4] 2> 242528 T779 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[68 (1436399879471497216)]} 0 0
[junit4:junit4] 2> 242528 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[68 (1436399879471497216)]} 0 2
[junit4:junit4] 2> 242529 T730 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68]} 0 5
[junit4:junit4] 2> 242531 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1436399879476740096)]} 0 0
[junit4:junit4] 2> 242537 T781 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[69 (1436399879480934400)]} 0 0
[junit4:junit4] 2> 242538 T746 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[69 (1436399879480934400)]} 0 3
[junit4:junit4] 2> 242539 T732 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69]} 0 6
[junit4:junit4] 2> 242542 T711 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1436399879488274432)]} 0 0
[junit4:junit4] 2> 242548 T761 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[70 (1436399879492468736)]} 0 0
[junit4:junit4] 2> 242549 T729 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[70 (1436399879492468736)]} 0 3
[junit4:junit4] 2> 242549 T747 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70]} 0 5
[junit4:junit4] 2> 242552 T712 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71 (1436399879497711616)]} 0 1
[junit4:junit4] 2> 242556 T778 C338 P57679 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[71 (1436399879500857344)]} 0 0
[junit4:junit4] 2> 242556 T745 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71 (1436399879500857344)]} 0 2
[junit4:junit4] 2> 242559 T709 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1436399879506100224)]} 0 1
[junit4:junit4] 2> 242565 T764 C339 P51762 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:45027/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[72 (1436399879510294528)]} 0 1
[junit4:junit4] 2> 242565 T731 C340 P45027 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46475/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[72 (1436399879510294528)]} 0 3
[junit4:junit4] 2> 242566 T748 C337 P46475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72]} 0 5
[junit4:junit4] 2> 242568 T710 C341 P42102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update
[...truncated too long message...]
junit4:junit4] 2> 409634 T694 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 409635 T694 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 409635 T694 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/index;done=false>>]
[junit4:junit4] 2> 409635 T694 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4/index
[junit4:junit4] 2> 409636 T694 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4;done=false>>]
[junit4:junit4] 2> 409636 T694 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674/jetty4
[junit4:junit4] 2> 409637 T866 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89774990732623884-127.0.0.1:57679_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 409639 T857 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4:junit4] 2> 409639 T857 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 0)
[junit4:junit4] 2> 409660 T694 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 409714 T694 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 409716 T694 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:55687 55687
[junit4:junit4] 2> 409818 T857 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@129e50d4 name:ZooKeeperConnection Watcher:127.0.0.1:55687/solr got event WatchedEvent state:Disconnected type:None path:null path:null type:None
[junit4:junit4] 2> 409818 T857 oascc.ConnectionManager.process Client->ZooKeeper status change trigger but we are already closed
[junit4:junit4] 2> 409820 T694 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 42102
[junit4:junit4] 2> !!!! WARNING: best effort to remove /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369857646674 FAILED !!!!!
[junit4:junit4] 2> 409821 T694 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 409821 T694 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:55687 55687
[junit4:junit4] 1> "core":"collection1_shard1_0_replica1",
[junit4:junit4] 1> "node_name":"127.0.0.1:51762_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:51762"}
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1_1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1_shard1_1_replica1",
[junit4:junit4] 1> "node_name":"127.0.0.1:51762_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:51762"}
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard2 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:46475_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:46475"}
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/shards (0)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/89774990732623875-127.0.0.1:42102__collection1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4:junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:42102_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:42102"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (6)
[junit4:junit4] 1> /solr/overseer_elect/election/89774990732623888-127.0.0.1:55687_solr-n_0000000007 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89774990732623884-127.0.0.1:57679_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89774990732623875-127.0.0.1:42102_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89774990732623886-127.0.0.1:45027_-n_0000000005 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89774990732623880-127.0.0.1:46475_-n_0000000002 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89774990732623882-127.0.0.1:51762_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89774990732623875-127.0.0.1:42102_-n_0000000000"}
[junit4:junit4] 1> /zookeeper (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 2> 409851 T768 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 409853 T768 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> 409853 T768 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeyShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=FDCDE5C093F55B8E -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_AR -Dtests.timezone=Antarctica/Macquarie -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 194s J0 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: Wrong doc count on shard1_1 expected:<419> but was:<418>
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([FDCDE5C093F55B8E:7C2B6BD8E4AA3BB2]:0)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(ShardSplitTest.java:167)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:155)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 409854 T694 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 193803 T693 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 410938 T785 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 410939 T785 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> 410939 T785 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=Lucene41(blocksize=128), _version_=MockFixedIntBlock(blockSize=1997)}, docValues:{}, sim=DefaultSimilarity, locale=es_AR, timezone=Antarctica/Macquarie
[junit4:junit4] 2> NOTE: Linux 3.2.0-44-generic amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=8,threads=1,free=87226624,total=323158016
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestDocumentBuilder, TestSchemaResource, DirectUpdateHandlerOptimizeTest, BadComponentTest, BasicDistributedZkTest, PluginInfoTest, BasicFunctionalityTest, TestRandomDVFaceting, BadCopyFieldTest, PolyFieldTest, PeerSyncTest, TestFastWriter, TestXIncludeConfig, MBeansHandlerTest, DistributedQueryElevationComponentTest, TestFieldTypeCollectionResource, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J0 in 195.08s, 1 test, 1 failure <<< FAILURES!
[...truncated 719 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:380: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:360: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1240: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:884: There were test failures: 295 suites, 1232 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 39 minutes 17 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure