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/19 11:00:32 UTC
[JENKINS] Lucene-Solr-trunk-Linux (64bit/jdk1.8.0-ea-b89) - Build #
5728 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/5728/
Java: 64bit/jdk1.8.0-ea-b89 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
shard2 is not consistent. Got 48 from http://127.0.0.1:43614/collection1lastClient and got 47 from http://127.0.0.1:54815/collection1
Stack Trace:
java.lang.AssertionError: shard2 is not consistent. Got 48 from http://127.0.0.1:43614/collection1lastClient and got 47 from http://127.0.0.1:54815/collection1
at __randomizedtesting.SeedInfo.seed([D70B922181ED5948:56ED1C39F6B23974]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:110)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:491)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Build Log:
[...truncated 9224 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 39074 T45 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 39083 T45 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-1368952930301
[junit4:junit4] 2> 39089 T45 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 39093 T46 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 39192 T45 oasc.ZkTestServer.run start zk server on port:33172
[junit4:junit4] 2> 39251 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 40077 T52 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3e03b65e name:ZooKeeperConnection Watcher:127.0.0.1:33172 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 40078 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 40078 T45 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 40108 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 40112 T54 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3780832e name:ZooKeeperConnection Watcher:127.0.0.1:33172/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 40112 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 40113 T45 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 40118 T45 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 40124 T45 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 40130 T45 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 40136 T45 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> 40143 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 40151 T45 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> 40151 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 40157 T45 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> 40157 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 40164 T45 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> 40164 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 40168 T45 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> 40169 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 40174 T45 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> 40174 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 40179 T45 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> 40179 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 40183 T45 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> 40184 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 40189 T45 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> 40190 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 40429 T45 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 40518 T45 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53328
[junit4:junit4] 2> 40531 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 40532 T45 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 40532 T45 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-1368952931411
[junit4:junit4] 2> 40532 T45 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-1368952931411/solr.xml
[junit4:junit4] 2> 40532 T45 oasc.CoreContainer.<init> New CoreContainer 1960895526
[junit4:junit4] 2> 40533 T45 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-1368952931411/'
[junit4:junit4] 2> 40533 T45 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-1368952931411/'
[junit4:junit4] 2> 40620 T45 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 40621 T45 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 40621 T45 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 40621 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 40621 T45 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 40622 T45 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 40622 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 40622 T45 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 40623 T45 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 40646 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 40902 T45 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 40903 T45 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:33172/solr
[junit4:junit4] 2> 40911 T45 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 40913 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 40918 T67 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2b09b456 name:ZooKeeperConnection Watcher:127.0.0.1:33172 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 40918 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 40926 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 40943 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 40946 T69 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2aa6d899 name:ZooKeeperConnection Watcher:127.0.0.1:33172/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 40946 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 40951 T45 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 40959 T45 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 40967 T45 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 40970 T45 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53328_
[junit4:junit4] 2> 40973 T45 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53328_
[junit4:junit4] 2> 40978 T45 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 40992 T45 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 40995 T45 oasc.Overseer.start Overseer (id=89715699247742979-127.0.0.1:53328_-n_0000000000) starting
[junit4:junit4] 2> 41004 T45 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 41011 T71 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 41011 T45 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 41015 T45 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 41019 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 41029 T70 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 41041 T72 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-1368952931411/collection1
[junit4:junit4] 2> 41042 T72 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 41043 T72 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 41043 T72 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 41046 T72 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-1368952931411/collection1/'
[junit4:junit4] 2> 41047 T72 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-1368952931411/collection1/lib/README' to classloader
[junit4:junit4] 2> 41047 T72 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-1368952931411/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 41102 T72 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 41170 T72 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 41172 T72 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 41208 T72 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 41656 T72 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 41658 T72 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 41660 T72 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 41666 T72 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 41718 T72 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 41719 T72 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-1368952931411/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/control/data/
[junit4:junit4] 2> 41719 T72 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2d58f731
[junit4:junit4] 2> 41720 T72 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 41721 T72 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/control/data
[junit4:junit4] 2> 41721 T72 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/control/data/index/
[junit4:junit4] 2> 41721 T72 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 41721 T72 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/control/data/index
[junit4:junit4] 2> 41724 T72 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@587b8ee0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@71333ead),segFN=segments_1,generation=1}
[junit4:junit4] 2> 41724 T72 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 41727 T72 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 41728 T72 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 41730 T72 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 41731 T72 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 41732 T72 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 41732 T72 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 41732 T72 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 41733 T72 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 41733 T72 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 41736 T72 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 41740 T72 oass.SolrIndexSearcher.<init> Opening Searcher@78d0becb main
[junit4:junit4] 2> 41741 T72 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/control/data/tlog
[junit4:junit4] 2> 41742 T72 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 41742 T72 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 41745 T73 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@78d0becb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 41747 T72 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 41747 T72 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 42537 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 42538 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53328_",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53328"}
[junit4:junit4] 2> 42539 T70 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 42544 T70 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 42557 T69 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> 42751 T72 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 42751 T72 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53328 collection:control_collection shard:shard1
[junit4:junit4] 2> 42754 T72 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 42762 T72 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 42773 T72 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 42776 T72 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 42777 T72 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 42777 T72 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53328/collection1/
[junit4:junit4] 2> 42777 T72 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 42777 T72 oasc.SyncStrategy.syncToMe http://127.0.0.1:53328/collection1/ has no replicas
[junit4:junit4] 2> 42778 T72 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53328/collection1/
[junit4:junit4] 2> 42778 T72 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 44064 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 44078 T69 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> 44090 T72 oasc.ZkController.register We are http://127.0.0.1:53328/collection1/ and leader is http://127.0.0.1:53328/collection1/
[junit4:junit4] 2> 44091 T72 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53328
[junit4:junit4] 2> 44091 T72 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 44091 T72 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 44091 T72 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 44094 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 44098 T45 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 44098 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 44130 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 44139 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 44143 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 44145 T76 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3da53181 name:ZooKeeperConnection Watcher:127.0.0.1:33172/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 44145 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 44147 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 44153 T45 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 44240 T45 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 44243 T45 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:43614
[junit4:junit4] 2> 44243 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 44244 T45 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 44244 T45 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-1368952935370
[junit4:junit4] 2> 44244 T45 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-1368952935370/solr.xml
[junit4:junit4] 2> 44245 T45 oasc.CoreContainer.<init> New CoreContainer 540039111
[junit4:junit4] 2> 44245 T45 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-1368952935370/'
[junit4:junit4] 2> 44245 T45 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-1368952935370/'
[junit4:junit4] 2> 44301 T45 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 44302 T45 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 44302 T45 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 44302 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 44303 T45 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 44303 T45 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 44303 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 44303 T45 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 44304 T45 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 44304 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 44308 T45 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 44309 T45 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:33172/solr
[junit4:junit4] 2> 44309 T45 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 44310 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 44312 T87 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@339b25ad name:ZooKeeperConnection Watcher:127.0.0.1:33172 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 44312 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 44314 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 44318 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 44320 T89 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@533e6bad name:ZooKeeperConnection Watcher:127.0.0.1:33172/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 44320 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 44328 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 45334 T45 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43614_
[junit4:junit4] 2> 45336 T45 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43614_
[junit4:junit4] 2> 45339 T69 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> 45340 T89 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 45340 T76 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 45342 T69 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 45348 T90 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-1368952935370/collection1
[junit4:junit4] 2> 45348 T90 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 45349 T90 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 45349 T90 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 45351 T90 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-1368952935370/collection1/'
[junit4:junit4] 2> 45352 T90 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-1368952935370/collection1/lib/README' to classloader
[junit4:junit4] 2> 45352 T90 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-1368952935370/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 45382 T90 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 45419 T90 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 45421 T90 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 45441 T90 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 45590 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 45591 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:53328_",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53328"}
[junit4:junit4] 2> 45598 T89 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> 45599 T69 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> 45598 T76 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> 45846 T90 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 45849 T90 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 45852 T90 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 45858 T90 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 45923 T90 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 45924 T90 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-1368952935370/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty1/
[junit4:junit4] 2> 45924 T90 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2d58f731
[junit4:junit4] 2> 45926 T90 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 45926 T90 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty1
[junit4:junit4] 2> 45927 T90 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty1/index/
[junit4:junit4] 2> 45927 T90 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 45928 T90 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty1/index
[junit4:junit4] 2> 45930 T90 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@351d9d4e lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f3aa0fe),segFN=segments_1,generation=1}
[junit4:junit4] 2> 45930 T90 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 45934 T90 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 45934 T90 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 45935 T90 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 45936 T90 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 45937 T90 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 45937 T90 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 45938 T90 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 45938 T90 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 45939 T90 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 45941 T90 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 45945 T90 oass.SolrIndexSearcher.<init> Opening Searcher@12a29fbd main
[junit4:junit4] 2> 45946 T90 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty1/tlog
[junit4:junit4] 2> 45946 T90 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 45947 T90 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 45952 T91 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12a29fbd main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 45955 T90 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 45956 T90 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 47107 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 47109 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:43614_",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43614"}
[junit4:junit4] 2> 47109 T70 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 47109 T70 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 47116 T76 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> 47116 T69 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> 47116 T89 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> 47958 T90 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 47959 T90 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43614 collection:collection1 shard:shard2
[junit4:junit4] 2> 47961 T90 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 47970 T90 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 47974 T90 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 47974 T90 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 47974 T90 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43614/collection1/
[junit4:junit4] 2> 47975 T90 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 47975 T90 oasc.SyncStrategy.syncToMe http://127.0.0.1:43614/collection1/ has no replicas
[junit4:junit4] 2> 47976 T90 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43614/collection1/
[junit4:junit4] 2> 47976 T90 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 48625 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 48637 T76 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> 48637 T69 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> 48637 T89 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> 48686 T90 oasc.ZkController.register We are http://127.0.0.1:43614/collection1/ and leader is http://127.0.0.1:43614/collection1/
[junit4:junit4] 2> 48687 T90 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43614
[junit4:junit4] 2> 48687 T90 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 48687 T90 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 48687 T90 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 48690 T90 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 48691 T45 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 48692 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 48693 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 48767 T45 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 48771 T45 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51901
[junit4:junit4] 2> 48772 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 48772 T45 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 48773 T45 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-1368952939914
[junit4:junit4] 2> 48773 T45 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-1368952939914/solr.xml
[junit4:junit4] 2> 48773 T45 oasc.CoreContainer.<init> New CoreContainer 1437273944
[junit4:junit4] 2> 48774 T45 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-1368952939914/'
[junit4:junit4] 2> 48774 T45 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-1368952939914/'
[junit4:junit4] 2> 48834 T45 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 48835 T45 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 48835 T45 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 48835 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 48836 T45 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 48836 T45 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 48836 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 48836 T45 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 48837 T45 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 48837 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 48841 T45 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 48841 T45 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:33172/solr
[junit4:junit4] 2> 48841 T45 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 48842 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 48844 T103 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28e9796c name:ZooKeeperConnection Watcher:127.0.0.1:33172 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 48844 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 48847 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 48850 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 48852 T105 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@31339c5a name:ZooKeeperConnection Watcher:127.0.0.1:33172/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 48852 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 48857 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 49861 T45 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51901_
[junit4:junit4] 2> 49862 T45 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51901_
[junit4:junit4] 2> 49865 T69 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> 49866 T76 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 49866 T89 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 49866 T89 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> 49866 T76 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> 49867 T105 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 49869 T69 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 49877 T106 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-1368952939914/collection1
[junit4:junit4] 2> 49878 T106 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 49879 T106 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 49879 T106 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 49880 T106 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-1368952939914/collection1/'
[junit4:junit4] 2> 49881 T106 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-1368952939914/collection1/lib/README' to classloader
[junit4:junit4] 2> 49881 T106 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-1368952939914/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 49912 T106 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 49945 T106 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 49947 T106 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 49967 T106 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 50145 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 50147 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:43614_",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43614"}
[junit4:junit4] 2> 50153 T105 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> 50153 T76 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> 50153 T69 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> 50155 T89 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> 50301 T106 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 50304 T106 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 50306 T106 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 50310 T106 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 50354 T106 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 50354 T106 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-1368952939914/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty2/
[junit4:junit4] 2> 50354 T106 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2d58f731
[junit4:junit4] 2> 50355 T106 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 50355 T106 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty2
[junit4:junit4] 2> 50355 T106 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty2/index/
[junit4:junit4] 2> 50356 T106 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 50356 T106 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty2/index
[junit4:junit4] 2> 50358 T106 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@66070a2f lockFactory=org.apache.lucene.store.NativeFSLockFactory@742c0be8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 50358 T106 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 50360 T106 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 50360 T106 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 50361 T106 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 50361 T106 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 50362 T106 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 50362 T106 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 50362 T106 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 50363 T106 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 50363 T106 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 50365 T106 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 50367 T106 oass.SolrIndexSearcher.<init> Opening Searcher@301a1b15 main
[junit4:junit4] 2> 50367 T106 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty2/tlog
[junit4:junit4] 2> 50368 T106 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 50368 T106 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 50371 T107 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@301a1b15 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 50373 T106 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 50373 T106 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 51665 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 51666 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51901_",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51901"}
[junit4:junit4] 2> 51666 T70 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 51666 T70 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 51673 T89 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> 51673 T69 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> 51673 T76 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> 51673 T105 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> 52375 T106 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 52375 T106 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51901 collection:collection1 shard:shard1
[junit4:junit4] 2> 52377 T106 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 52386 T106 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 52389 T106 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 52390 T106 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 52390 T106 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51901/collection1/
[junit4:junit4] 2> 52390 T106 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 52391 T106 oasc.SyncStrategy.syncToMe http://127.0.0.1:51901/collection1/ has no replicas
[junit4:junit4] 2> 52391 T106 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51901/collection1/
[junit4:junit4] 2> 52391 T106 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 53182 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53194 T69 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> 53194 T105 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> 53194 T89 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> 53194 T76 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> 53202 T106 oasc.ZkController.register We are http://127.0.0.1:51901/collection1/ and leader is http://127.0.0.1:51901/collection1/
[junit4:junit4] 2> 53203 T106 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51901
[junit4:junit4] 2> 53203 T106 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 53203 T106 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 53203 T106 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 53205 T106 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53207 T45 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 53207 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 53208 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 53300 T45 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 53303 T45 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54815
[junit4:junit4] 2> 53303 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 53304 T45 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 53304 T45 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-1368952944428
[junit4:junit4] 2> 53304 T45 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-1368952944428/solr.xml
[junit4:junit4] 2> 53305 T45 oasc.CoreContainer.<init> New CoreContainer 917433888
[junit4:junit4] 2> 53305 T45 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-1368952944428/'
[junit4:junit4] 2> 53305 T45 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-1368952944428/'
[junit4:junit4] 2> 53358 T45 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 53359 T45 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 53359 T45 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 53359 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 53360 T45 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 53360 T45 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 53360 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 53361 T45 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 53361 T45 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 53362 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 53367 T45 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 53367 T45 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:33172/solr
[junit4:junit4] 2> 53367 T45 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 53368 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 53370 T119 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5cc4fe1d name:ZooKeeperConnection Watcher:127.0.0.1:33172 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 53371 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 53373 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 53377 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 53379 T121 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5fcc2936 name:ZooKeeperConnection Watcher:127.0.0.1:33172/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 53379 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 53387 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 54392 T45 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54815_
[junit4:junit4] 2> 54393 T45 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54815_
[junit4:junit4] 2> 54396 T89 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> 54396 T69 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> 54396 T105 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> 54397 T76 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 54397 T76 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> 54399 T121 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 54399 T69 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 54400 T105 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 54400 T89 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 54405 T122 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-1368952944428/collection1
[junit4:junit4] 2> 54406 T122 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 54406 T122 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 54407 T122 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 54408 T122 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-1368952944428/collection1/'
[junit4:junit4] 2> 54409 T122 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-1368952944428/collection1/lib/README' to classloader
[junit4:junit4] 2> 54409 T122 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-1368952944428/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 54441 T122 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 54473 T122 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 54475 T122 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 54491 T122 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 54702 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 54703 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:51901_",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51901"}
[junit4:junit4] 2> 54708 T105 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> 54708 T121 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> 54708 T89 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> 54708 T69 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> 54709 T76 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> 54834 T122 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 54836 T122 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 54837 T122 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 54842 T122 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 54891 T122 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 54891 T122 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-1368952944428/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty3/
[junit4:junit4] 2> 54892 T122 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2d58f731
[junit4:junit4] 2> 54892 T122 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 54893 T122 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty3
[junit4:junit4] 2> 54893 T122 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty3/index/
[junit4:junit4] 2> 54893 T122 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 54893 T122 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty3/index
[junit4:junit4] 2> 54895 T122 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73f966b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1bbbff93),segFN=segments_1,generation=1}
[junit4:junit4] 2> 54895 T122 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 54897 T122 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 54898 T122 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 54898 T122 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 54899 T122 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 54899 T122 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 54899 T122 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 54900 T122 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 54900 T122 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 54900 T122 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 54902 T122 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 54904 T122 oass.SolrIndexSearcher.<init> Opening Searcher@74aa281e main
[junit4:junit4] 2> 54905 T122 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty3/tlog
[junit4:junit4] 2> 54905 T122 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 54905 T122 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 54912 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@74aa281e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 54914 T122 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 54914 T122 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 56216 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 56217 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54815_",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54815"}
[junit4:junit4] 2> 56217 T70 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 56218 T70 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 56224 T89 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> 56224 T121 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> 56224 T105 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> 56224 T69 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> 56224 T76 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> 56917 T122 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 56918 T122 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54815 collection:collection1 shard:shard2
[junit4:junit4] 2> 56922 T122 oasc.ZkController.register We are http://127.0.0.1:54815/collection1/ and leader is http://127.0.0.1:43614/collection1/
[junit4:junit4] 2> 56922 T122 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54815
[junit4:junit4] 2> 56922 T122 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 56923 T122 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C3 name=collection1 org.apache.solr.core.SolrCore@760dabb url=http://127.0.0.1:54815/collection1 node=127.0.0.1:54815_ C3_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, node_name=127.0.0.1:54815_, state=down, base_url=http://127.0.0.1:54815}
[junit4:junit4] 2> 56927 T124 C3 P54815 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 56928 T124 C3 P54815 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 56928 T122 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 56928 T124 C3 P54815 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 56929 T124 C3 P54815 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 56930 T45 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 56930 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 56931 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 56932 T124 C3 P54815 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 57036 T45 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 57039 T45 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:42384
[junit4:junit4] 2> 57040 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 57040 T45 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 57041 T45 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-1368952948151
[junit4:junit4] 2> 57041 T45 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-1368952948151/solr.xml
[junit4:junit4] 2> 57042 T45 oasc.CoreContainer.<init> New CoreContainer 2007035963
[junit4:junit4] 2> 57042 T45 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-1368952948151/'
[junit4:junit4] 2> 57042 T45 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-1368952948151/'
[junit4:junit4] 2> 57122 T45 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 57123 T45 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 57123 T45 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 57123 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 57124 T45 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 57124 T45 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 57124 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 57124 T45 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 57125 T45 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 57125 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 57129 T45 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 57129 T45 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:33172/solr
[junit4:junit4] 2> 57130 T45 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 57131 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 57133 T136 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@563a1d4a name:ZooKeeperConnection Watcher:127.0.0.1:33172 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 57133 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 57135 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 57141 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 57143 T138 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10dd09ff name:ZooKeeperConnection Watcher:127.0.0.1:33172/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 57144 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 57149 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 57250 T85 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 57732 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 57734 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:54815_",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54815"}
[junit4:junit4] 2> 57740 T69 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> 57741 T121 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> 57741 T76 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> 57740 T105 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> 57740 T138 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> 57740 T89 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> 58155 T45 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42384_
[junit4:junit4] 2> 58156 T45 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42384_
[junit4:junit4] 2> 58159 T76 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> 58160 T138 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 58159 T105 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> 58159 T69 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> 58161 T138 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> 58160 T121 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 58163 T76 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 58160 T89 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 58164 T89 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> 58163 T121 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> 58165 T105 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 58166 T69 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 58170 T139 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-1368952948151/collection1
[junit4:junit4] 2> 58171 T139 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 58172 T139 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 58172 T139 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 58175 T139 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-1368952948151/collection1/'
[junit4:junit4] 2> 58176 T139 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-1368952948151/collection1/lib/README' to classloader
[junit4:junit4] 2> 58177 T139 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-1368952948151/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 58227 T139 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 58254 T85 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 58255 T85 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:54815_&version=2&coreNodeName=4&wt=javabin&core=collection1&state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY} status=0 QTime=1005
[junit4:junit4] 2> 58268 T139 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 58271 T139 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 58290 T139 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 58695 T139 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 58711 T139 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 58713 T139 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 58718 T139 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 58765 T139 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 58765 T139 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-1368952948151/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/
[junit4:junit4] 2> 58765 T139 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2d58f731
[junit4:junit4] 2> 58766 T139 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 58767 T139 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4
[junit4:junit4] 2> 58768 T139 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/index/
[junit4:junit4] 2> 58768 T139 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 58769 T139 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/index
[junit4:junit4] 2> 58772 T139 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c7aa0f9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fdd3541),segFN=segments_1,generation=1}
[junit4:junit4] 2> 58773 T139 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 58776 T139 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 58777 T139 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 58778 T139 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 58779 T139 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 58780 T139 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 58780 T139 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 58781 T139 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 58782 T139 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 58783 T139 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 58786 T139 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 58790 T139 oass.SolrIndexSearcher.<init> Opening Searcher@23ed2ca1 main
[junit4:junit4] 2> 58790 T139 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/tlog
[junit4:junit4] 2> 58791 T139 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 58791 T139 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 58797 T140 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@23ed2ca1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 58799 T139 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 58800 T139 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 59252 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 59253 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:42384_",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42384"}
[junit4:junit4] 2> 59253 T70 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 59254 T70 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 59259 T138 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> 59259 T89 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> 59259 T121 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> 59259 T69 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> 59259 T76 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> 59259 T105 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> 59802 T139 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 59802 T139 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42384 collection:collection1 shard:shard1
[junit4:junit4] 2> 59806 T139 oasc.ZkController.register We are http://127.0.0.1:42384/collection1/ and leader is http://127.0.0.1:51901/collection1/
[junit4:junit4] 2> 59806 T139 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42384
[junit4:junit4] 2> 59807 T139 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 59807 T139 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C4 name=collection1 org.apache.solr.core.SolrCore@2aec26a5 url=http://127.0.0.1:42384/collection1 node=127.0.0.1:42384_ C4_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, node_name=127.0.0.1:42384_, state=down, base_url=http://127.0.0.1:42384}
[junit4:junit4] 2> 59807 T141 C4 P42384 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 59808 T141 C4 P42384 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 59808 T139 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 59808 T141 C4 P42384 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 59809 T141 C4 P42384 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 59810 T45 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 59810 T141 C4 P42384 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 59810 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 59811 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 59814 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 59816 T100 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 59817 T45 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 59817 T45 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 59818 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C3_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, shard=shard2, node_name=127.0.0.1:54815_, state=recovering, base_url=http://127.0.0.1:54815}
[junit4:junit4] 2> 60299 T124 C3 P54815 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:43614/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 60302 T124 C3 P54815 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 60307 T124 C3 P54815 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:54815 START replicas=[http://127.0.0.1:43614/collection1/] nUpdates=100
[junit4:junit4] 2> 60309 T124 C3 P54815 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 60310 T124 C3 P54815 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 60310 T124 C3 P54815 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 60310 T124 C3 P54815 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 60310 T124 C3 P54815 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 60310 T124 C3 P54815 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:43614/collection1/. core=collection1
[junit4:junit4] 2> 60311 T124 C3 P54815 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C5 name=collection1 org.apache.solr.core.SolrCore@4fae89b5 url=http://127.0.0.1:43614/collection1 node=127.0.0.1:43614_ C5_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, shard=shard2, node_name=127.0.0.1:43614_, state=active, base_url=http://127.0.0.1:43614, leader=true}
[junit4:junit4] 2> 60324 T84 C5 P43614 oasc.SolrCore.execute [collection1] webapp= path=/get params={version=2&wt=javabin&getVersions=100&qt=/get&distrib=false} status=0 QTime=2
[junit4:junit4] 2> 60327 T82 C5 P43614 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 60329 T82 C5 P43614 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@351d9d4e lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f3aa0fe),segFN=segments_1,generation=1}
[junit4:junit4] 2> 60330 T82 C5 P43614 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 60330 T82 C5 P43614 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@351d9d4e lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f3aa0fe),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@351d9d4e lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f3aa0fe),segFN=segments_2,generation=2}
[junit4:junit4] 2> 60331 T82 C5 P43614 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 60331 T82 C5 P43614 oass.SolrIndexSearcher.<init> Opening Searcher@6f53fae9 realtime
[junit4:junit4] 2> 60331 T82 C5 P43614 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 60331 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&waitSearcher=true&openSearcher=false&softCommit=false&commit=true&commit_end_point=true} {commit=} 0 9
[junit4:junit4] 2> 60350 T124 C3 P54815 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 60351 T124 C3 P54815 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 2> 60356 T124 C3 P54815 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 60370 T83 C5 P43614 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 60370 T83 C5 P43614 oasc.SolrCore.execute [collection1] webapp= path=/replication params={version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=12
[junit4:junit4] 2> 60372 T124 C3 P54815 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 60372 T124 C3 P54815 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 60372 T124 C3 P54815 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 60375 T84 C5 P43614 oasc.SolrCore.execute [collection1] webapp= path=/replication params={version=2&generation=2&wt=javabin&qt=/replication&command=filelist} status=0 QTime=0
[junit4:junit4] 2> 60376 T124 C3 P54815 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 60378 T124 C3 P54815 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty3/index.20130518234231592
[junit4:junit4] 2> 60378 T124 C3 P54815 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@4475a488 lockFactory=org.apache.lucene.store.NativeFSLockFactory@d52488f) fullCopy=false
[junit4:junit4] 2> 60383 T82 C5 P43614 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=2&checksum=true&file=segments_2&wt=filestream&qt=/replication&command=filecontent} status=0 QTime=1
[junit4:junit4] 2> 60391 T124 C3 P54815 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 60398 T124 C3 P54815 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 60398 T124 C3 P54815 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 60401 T124 C3 P54815 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73f966b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1bbbff93),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73f966b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1bbbff93),segFN=segments_2,generation=2}
[junit4:junit4] 2> 60402 T124 C3 P54815 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 60402 T124 C3 P54815 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 60402 T124 C3 P54815 oass.SolrIndexSearcher.<init> Opening Searcher@6f8c4931 main
[junit4:junit4] 2> 60403 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6f8c4931 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 60404 T124 C3 P54815 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty3/index.20130518234231592 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty3/index.20130518234231592;done=true>>]
[junit4:junit4] 2> 60404 T124 C3 P54815 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty3/index.20130518234231592
[junit4:junit4] 2> 60404 T124 C3 P54815 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty3/index.20130518234231592
[junit4:junit4] 2> 60404 T124 C3 P54815 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 60405 T124 C3 P54815 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 60405 T124 C3 P54815 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 60405 T124 C3 P54815 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 60406 T124 C3 P54815 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 60766 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 60768 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:42384_",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42384"}
[junit4:junit4] 2> 60775 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:54815_",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54815"}
[junit4:junit4] 2> 60781 T76 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> 60782 T69 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> 60781 T138 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> 60782 T121 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> 60782 T89 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> 60782 T105 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> 60817 T100 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 60818 T100 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:42384_&version=2&coreNodeName=5&wt=javabin&core=collection1&state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY} status=0 QTime=1002
[junit4:junit4] 2> 60820 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 61823 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C4_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, shard=shard1, node_name=127.0.0.1:42384_, state=recovering, base_url=http://127.0.0.1:42384}
[junit4:junit4] 2> 62819 T141 C4 P42384 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:51901/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 62819 T141 C4 P42384 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:42384 START replicas=[http://127.0.0.1:51901/collection1/] nUpdates=100
[junit4:junit4] 2> 62820 T141 C4 P42384 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 62820 T141 C4 P42384 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 62820 T141 C4 P42384 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 62821 T141 C4 P42384 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 62821 T141 C4 P42384 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 62821 T141 C4 P42384 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:51901/collection1/. core=collection1
[junit4:junit4] 2> 62822 T141 C4 P42384 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 62825 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C6 name=collection1 org.apache.solr.core.SolrCore@363a433c url=http://127.0.0.1:51901/collection1 node=127.0.0.1:51901_ C6_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, shard=shard1, node_name=127.0.0.1:51901_, state=active, base_url=http://127.0.0.1:51901, leader=true}
[junit4:junit4] 2> 62827 T101 C6 P51901 oasc.SolrCore.execute [collection1] webapp= path=/get params={version=2&wt=javabin&getVersions=100&qt=/get&distrib=false} status=0 QTime=1
[junit4:junit4] 2> 62829 T99 C6 P51901 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 62831 T99 C6 P51901 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@66070a2f lockFactory=org.apache.lucene.store.NativeFSLockFactory@742c0be8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 62831 T99 C6 P51901 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 62833 T99 C6 P51901 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@66070a2f lockFactory=org.apache.lucene.store.NativeFSLockFactory@742c0be8),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@66070a2f lockFactory=org.apache.lucene.store.NativeFSLockFactory@742c0be8),segFN=segments_2,generation=2}
[junit4:junit4] 2> 62833 T99 C6 P51901 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 62833 T99 C6 P51901 oass.SolrIndexSearcher.<init> Opening Searcher@3fbc6e66 realtime
[junit4:junit4] 2> 62834 T99 C6 P51901 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 62834 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&waitSearcher=true&openSearcher=false&softCommit=false&commit=true&commit_end_point=true} {commit=} 0 5
[junit4:junit4] 2> 62835 T141 C4 P42384 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 62835 T141 C4 P42384 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 62838 T98 C6 P51901 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 62838 T98 C6 P51901 oasc.SolrCore.execute [collection1] webapp= path=/replication params={version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=0
[junit4:junit4] 2> 62839 T141 C4 P42384 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 62839 T141 C4 P42384 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 62840 T141 C4 P42384 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 62842 T99 C6 P51901 oasc.SolrCore.execute [collection1] webapp= path=/replication params={version=2&generation=2&wt=javabin&qt=/replication&command=filelist} status=0 QTime=0
[junit4:junit4] 2> 62843 T141 C4 P42384 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 62844 T141 C4 P42384 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/index.20130518234234059
[junit4:junit4] 2> 62844 T141 C4 P42384 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@25c13a51 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d8b9569) fullCopy=false
[junit4:junit4] 2> 62847 T100 C6 P51901 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=2&checksum=true&file=segments_2&wt=filestream&qt=/replication&command=filecontent} status=0 QTime=0
[junit4:junit4] 2> 62848 T141 C4 P42384 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 62850 T141 C4 P42384 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 62850 T141 C4 P42384 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 62851 T141 C4 P42384 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c7aa0f9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fdd3541),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c7aa0f9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fdd3541),segFN=segments_2,generation=2}
[junit4:junit4] 2> 62852 T141 C4 P42384 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 62852 T141 C4 P42384 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 62852 T141 C4 P42384 oass.SolrIndexSearcher.<init> Opening Searcher@70d27b44 main
[junit4:junit4] 2> 62853 T140 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@70d27b44 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 62853 T141 C4 P42384 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/index.20130518234234059 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/index.20130518234234059;done=true>>]
[junit4:junit4] 2> 62854 T141 C4 P42384 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/index.20130518234234059
[junit4:junit4] 2> 62854 T141 C4 P42384 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/index.20130518234234059
[junit4:junit4] 2> 62854 T141 C4 P42384 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 62854 T141 C4 P42384 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 62854 T141 C4 P42384 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 62854 T141 C4 P42384 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 62856 T141 C4 P42384 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 63798 T70 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 63799 T70 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:42384_",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42384"}
[junit4:junit4] 2> 63804 T69 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> 63805 T89 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> 63805 T121 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> 63804 T76 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> 63805 T138 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> 63805 T105 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> 63827 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 63829 T45 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C7 name=collection1 org.apache.solr.core.SolrCore@2967d20a url=http://127.0.0.1:53328/collection1 node=127.0.0.1:53328_ C7_STATE=coll:control_collection core:collection1 props:{core=collection1, collection=control_collection, shard=shard1, node_name=127.0.0.1:53328_, state=active, base_url=http://127.0.0.1:53328, leader=true}
[junit4:junit4] 2> 63834 T65 C7 P53328 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 63837 T65 C7 P53328 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@587b8ee0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@71333ead),segFN=segments_1,generation=1}
[junit4:junit4] 2> 63837 T65 C7 P53328 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 63838 T65 C7 P53328 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@587b8ee0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@71333ead),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@587b8ee0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@71333ead),segFN=segments_2,generation=2}
[junit4:junit4] 2> 63838 T65 C7 P53328 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 63838 T65 C7 P53328 oass.SolrIndexSearcher.<init> Opening Searcher@282cba1a main
[junit4:junit4] 2> 63839 T65 C7 P53328 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 63840 T73 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@282cba1a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 63840 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&waitSearcher=true&softCommit=false&commit=true} {commit=} 0 6
[junit4:junit4] 2> 63848 T84 C5 P43614 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 63849 T84 C5 P43614 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@351d9d4e lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f3aa0fe),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@351d9d4e lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f3aa0fe),segFN=segments_3,generation=3}
[junit4:junit4] 2> 63849 T84 C5 P43614 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 63850 T84 C5 P43614 oass.SolrIndexSearcher.<init> Opening Searcher@7ca5c255 main
[junit4:junit4] 2> 63850 T84 C5 P43614 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 63851 T91 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7ca5c255 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 63856 T84 C5 P43614 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:51901/collection1/, StdNode: http://127.0.0.1:42384/collection1/, StdNode: http://127.0.0.1:54815/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 63862 T101 C6 P51901 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 63864 T101 C6 P51901 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@66070a2f lockFactory=org.apache.lucene.store.NativeFSLockFactory@742c0be8),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@66070a2f lockFactory=org.apache.lucene.store.NativeFSLockFactory@742c0be8),segFN=segments_3,generation=3}
[junit4:junit4] 2> 63864 T101 C6 P51901 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 63864 T101 C6 P51901 oass.SolrIndexSearcher.<init> Opening Searcher@63118faf main
[junit4:junit4] 2> 63865 T101 C6 P51901 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 63866 T107 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@63118faf main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 63867 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&version=2&wt=javabin&waitSearcher=true&softCommit=false&commit=true&commit_end_point=true} {commit=} 0 5
[junit4:junit4] 2> C3_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, shard=shard2, node_name=127.0.0.1:54815_, state=active, base_url=http://127.0.0.1:54815}
[junit4:junit4] 2> 63867 T115 C3 P54815 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 63868 T115 C3 P54815 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73f966b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1bbbff93),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73f966b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1bbbff93),segFN=segments_3,generation=3}
[junit4:junit4] 2> C4_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, shard=shard1, node_name=127.0.0.1:42384_, state=active, base_url=http://127.0.0.1:42384}
[junit4:junit4] 2> 63868 T134 C4 P42384 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 63868 T115 C3 P54815 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 63869 T134 C4 P42384 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c7aa0f9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fdd3541),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3c7aa0f9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fdd3541),segFN=segments_3,generation=3}
[junit4:junit4] 2> 63870 T134 C4 P42384 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 63870 T115 C3 P54815 oass.SolrIndexSearcher.<init> Opening Searcher@9925330 main
[junit4:junit4] 2> 63871 T134 C4 P42384 oass.SolrIndexSearcher.<init> Opening Searcher@d37d303 main
[junit4:junit4] 2> 63871 T115 C3 P54815 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 63871 T134 C4 P42384 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 63872 T123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9925330 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 63872 T140 oasc.JmxMonitoredMap.put WARN Failed to register info bean: fieldValueCache javax.management.InstanceAlreadyExistsException: solr/collection1:type=fieldValueCache,id=org.apache.solr.search.FastLRUCache
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:513)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:303)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1784)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:131)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1661)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 63873 T140 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d37d303 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 63872 T115 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&version=2&wt=javabin&waitSearcher=true&softCommit=false&commit=true&commit_end_point=true} {commit=} 0 5
[junit4:junit4] 2> 63873 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&version=2&wt=javabin&waitSearcher=true&softCommit=false&commit=true&commit_end_point=true} {commit=} 0 5
[junit4:junit4] 2> 63874 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&waitSearcher=true&softCommit=false&commit=true} {commit=} 0 26
[junit4:junit4] 2> 63875 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 63879 T82 C5 P43614 oasc.SolrCore.execute [collection1] webapp= path=/select params={version=2&rows=0&wt=javabin&tests=checkShardConsistency&q=*:*&distrib=false} hits=0 status=0 QTime=1
[junit4:junit4] 2> 63881 T114 C3 P54815 oasc.SolrCore.execute [collection1] webapp= path=/select params={version=2&rows=0&wt=javabin&tests=checkShardConsistency&q=*:*&distrib=false} hits=0 status=0 QTime=0
[junit4:junit4] 2> 63884 T99 C6 P51901 oasc.SolrCore.execute [collection1] webapp= path=/select params={version=2&rows=0&wt=javabin&tests=checkShardConsistency&q=*:*&distrib=false} hits=0 status=0 QTime=0
[junit4:junit4] 2> 63887 T133 C4 P42384 oasc.SolrCore.execute [collection1] webapp= path=/select params={version=2&rows=0&wt=javabin&tests=checkShardConsistency&q=*:*&distrib=false} hits=0 status=0 QTime=1
[junit4:junit4] 2> 65923 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1435451215966109696)} 0 19
[junit4:junit4] 2> 65934 T114 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.from=http://127.0.0.1:43614/collection1/&version=2&wt=javabin&update.distrib=FROMLEADER&_version_=-1435451215988129792} {deleteByQuery=*:* (-1435451215988129792)} 0 1
[junit4:junit4] 2> 65937 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.from=http://127.0.0.1:51901/collection1/&version=2&wt=javabin&update.distrib=FROMLEADER&_version_=-1435451215993372672} {deleteByQuery=*:* (-1435451215993372672)} 0 1
[junit4:junit4] 2> 65938 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER} {deleteByQuery=*:* (-1435451215993372672)} 0 7
[junit4:junit4] 2> 65938 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1435451215988129792)} 0 12
[junit4:junit4] 2> 65944 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[0 (1435451216005955584)]} 0 3
[junit4:junit4] 2> 65953 T131 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[0 (1435451216009101312)]} 0 1
[junit4:junit4] 2> 65954 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[0 (1435451216009101312)]} 0 8
[junit4:junit4] 2> 65958 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[1 (1435451216020635648)]} 0 1
[junit4:junit4] 2> 65970 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[1 (1435451216029024256)]} 0 1
[junit4:junit4] 2> 65971 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[1 (1435451216029024256)]} 0 6
[junit4:junit4] 2> 65972 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[1]} 0 11
[junit4:junit4] 2> 65976 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[2 (1435451216039510016)]} 0 1
[junit4:junit4] 2> 65984 T117 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[2 (1435451216043704320)]} 0 2
[junit4:junit4] 2> 65985 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[2 (1435451216043704320)]} 0 6
[junit4:junit4] 2> 65989 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[3 (1435451216053141504)]} 0 1
[junit4:junit4] 2> 65999 T116 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[3 (1435451216060481536)]} 0 1
[junit4:junit4] 2> 66000 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[3 (1435451216060481536)]} 0 6
[junit4:junit4] 2> 66001 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[3]} 0 9
[junit4:junit4] 2> 66004 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[4 (1435451216068870144)]} 0 1
[junit4:junit4] 2> 66010 T133 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[4 (1435451216073064448)]} 0 0
[junit4:junit4] 2> 66011 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[4 (1435451216073064448)]} 0 5
[junit4:junit4] 2> 66015 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[5 (1435451216080404480)]} 0 1
[junit4:junit4] 2> 66021 T115 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[5 (1435451216084598784)]} 0 1
[junit4:junit4] 2> 66022 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[5 (1435451216084598784)]} 0 4
[junit4:junit4] 2> 66025 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[6 (1435451216091938816)]} 0 0
[junit4:junit4] 2> 66032 T114 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[6 (1435451216095084544)]} 0 1
[junit4:junit4] 2> 66032 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[6 (1435451216095084544)]} 0 4
[junit4:junit4] 2> 66036 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[7 (1435451216103473152)]} 0 1
[junit4:junit4] 2> 66046 T117 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[7 (1435451216109764608)]} 0 1
[junit4:junit4] 2> 66047 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[7 (1435451216109764608)]} 0 5
[junit4:junit4] 2> 66048 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[7]} 0 9
[junit4:junit4] 2> 66051 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[8 (1435451216119201792)]} 0 1
[junit4:junit4] 2> 66061 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[8 (1435451216125493248)]} 0 1
[junit4:junit4] 2> 66062 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[8 (1435451216125493248)]} 0 5
[junit4:junit4] 2> 66063 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[8]} 0 9
[junit4:junit4] 2> 66066 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[9 (1435451216134930432)]} 0 1
[junit4:junit4] 2> 66075 T116 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[9 (1435451216141221888)]} 0 0
[junit4:junit4] 2> 66076 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[9 (1435451216141221888)]} 0 4
[junit4:junit4] 2> 66077 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[9]} 0 8
[junit4:junit4] 2> 66080 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[10 (1435451216149610496)]} 0 0
[junit4:junit4] 2> 66090 T131 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[10 (1435451216155901952)]} 0 1
[junit4:junit4] 2> 66091 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[10 (1435451216155901952)]} 0 5
[junit4:junit4] 2> 66091 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[10]} 0 8
[junit4:junit4] 2> 66095 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[11 (1435451216165339136)]} 0 1
[junit4:junit4] 2> 66104 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[11 (1435451216169533440)]} 0 1
[junit4:junit4] 2> 66105 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[11 (1435451216169533440)]} 0 6
[junit4:junit4] 2> 66109 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[12 (1435451216178970624)]} 0 1
[junit4:junit4] 2> 66121 T133 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[12 (1435451216187359232)]} 0 1
[junit4:junit4] 2> 66122 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[12 (1435451216187359232)]} 0 6
[junit4:junit4] 2> 66122 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[12]} 0 10
[junit4:junit4] 2> 66126 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[13 (1435451216197844992)]} 0 1
[junit4:junit4] 2> 66137 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[13 (1435451216204136448)]} 0 1
[junit4:junit4] 2> 66138 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[13 (1435451216204136448)]} 0 6
[junit4:junit4] 2> 66138 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[13]} 0 8
[junit4:junit4] 2> 66142 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[14 (1435451216213573632)]} 0 1
[junit4:junit4] 2> 66149 T131 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[14 (1435451216217767936)]} 0 1
[junit4:junit4] 2> 66150 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[14 (1435451216217767936)]} 0 5
[junit4:junit4] 2> 66154 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[15 (1435451216227205120)]} 0 1
[junit4:junit4] 2> 66161 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[15 (1435451216230350848)]} 0 1
[junit4:junit4] 2> 66162 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[15 (1435451216230350848)]} 0 5
[junit4:junit4] 2> 66166 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[16 (1435451216238739456)]} 0 1
[junit4:junit4] 2> 66177 T133 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[16 (1435451216247128064)]} 0 1
[junit4:junit4] 2> 66178 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[16 (1435451216247128064)]} 0 5
[junit4:junit4] 2> 66179 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[16]} 0 10
[junit4:junit4] 2> 66183 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[17 (1435451216256565248)]} 0 1
[junit4:junit4] 2> 66192 T115 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[17 (1435451216263905280)]} 0 0
[junit4:junit4] 2> 66193 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[17 (1435451216263905280)]} 0 5
[junit4:junit4] 2> 66194 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[17]} 0 8
[junit4:junit4] 2> 66198 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[18 (1435451216272293888)]} 0 1
[junit4:junit4] 2> 66209 T114 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[18 (1435451216280682496)]} 0 1
[junit4:junit4] 2> 66210 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[18 (1435451216280682496)]} 0 5
[junit4:junit4] 2> 66211 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[18]} 0 9
[junit4:junit4] 2> 66215 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[19 (1435451216290119680)]} 0 2
[junit4:junit4] 2> 66222 T117 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[19 (1435451216294313984)]} 0 1
[junit4:junit4] 2> 66223 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[19 (1435451216294313984)]} 0 5
[junit4:junit4] 2> 66227 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[20 (1435451216302702592)]} 0 1
[junit4:junit4] 2> 66237 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[20 (1435451216310042624)]} 0 1
[junit4:junit4] 2> 66238 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[20 (1435451216310042624)]} 0 6
[junit4:junit4] 2> 66238 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[20]} 0 8
[junit4:junit4] 2> 66242 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[21 (1435451216318431232)]} 0 1
[junit4:junit4] 2> 66249 T116 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[21 (1435451216322625536)]} 0 1
[junit4:junit4] 2> 66250 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[21 (1435451216322625536)]} 0 5
[junit4:junit4] 2> 66254 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[22 (1435451216331014144)]} 0 1
[junit4:junit4] 2> 66266 T131 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[22 (1435451216339402752)]} 0 1
[junit4:junit4] 2> 66267 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[22 (1435451216339402752)]} 0 6
[junit4:junit4] 2> 66268 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[22]} 0 11
[junit4:junit4] 2> 66273 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[23 (1435451216350937088)]} 0 1
[junit4:junit4] 2> 66284 T115 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[23 (1435451216359325696)]} 0 1
[junit4:junit4] 2> 66285 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[23 (1435451216359325696)]} 0 6
[junit4:junit4] 2> 66285 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[23]} 0 9
[junit4:junit4] 2> 66289 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[24 (1435451216368762880)]} 0 1
[junit4:junit4] 2> 66299 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[24 (1435451216375054336)]} 0 1
[junit4:junit4] 2> 66300 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[24 (1435451216375054336)]} 0 5
[junit4:junit4] 2> 66301 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[24]} 0 9
[junit4:junit4] 2> 66305 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[25 (1435451216384491520)]} 0 1
[junit4:junit4] 2> 66315 T116 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[25 (1435451216391831552)]} 0 1
[junit4:junit4] 2> 66316 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[25 (1435451216391831552)]} 0 5
[junit4:junit4] 2> 66316 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[25]} 0 8
[junit4:junit4] 2> 66320 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[26 (1435451216401268736)]} 0 1
[junit4:junit4] 2> 66331 T114 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[26 (1435451216407560192)]} 0 1
[junit4:junit4] 2> 66332 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[26 (1435451216407560192)]} 0 6
[junit4:junit4] 2> 66333 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[26]} 0 9
[junit4:junit4] 2> 66337 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[27 (1435451216418045952)]} 0 1
[junit4:junit4] 2> 66348 T133 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[27 (1435451216425385984)]} 0 1
[junit4:junit4] 2> 66349 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[27 (1435451216425385984)]} 0 6
[junit4:junit4] 2> 66350 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[27]} 0 9
[junit4:junit4] 2> 66354 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[28 (1435451216435871744)]} 0 1
[junit4:junit4] 2> 66365 T131 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[28 (1435451216444260352)]} 0 1
[junit4:junit4] 2> 66366 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[28 (1435451216444260352)]} 0 6
[junit4:junit4] 2> 66367 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[28]} 0 10
[junit4:junit4] 2> 66371 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[29 (1435451216453697536)]} 0 1
[junit4:junit4] 2> 66382 T115 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[29 (1435451216462086144)]} 0 1
[junit4:junit4] 2> 66383 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[29 (1435451216462086144)]} 0 6
[junit4:junit4] 2> 66384 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[29]} 0 10
[junit4:junit4] 2> 66388 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[30 (1435451216472571904)]} 0 0
[junit4:junit4] 2> 66398 T117 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[30 (1435451216478863360)]} 0 1
[junit4:junit4] 2> 66398 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[30 (1435451216478863360)]} 0 4
[junit4:junit4] 2> 66399 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[30]} 0 8
[junit4:junit4] 2> 66403 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[31 (1435451216488300544)]} 0 1
[junit4:junit4] 2> 66411 T116 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[31 (1435451216492494848)]} 0 1
[junit4:junit4] 2> 66412 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[31 (1435451216492494848)]} 0 5
[junit4:junit4] 2> 66415 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[32 (1435451216500883456)]} 0 1
[junit4:junit4] 2> 66425 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[32 (1435451216507174912)]} 0 0
[junit4:junit4] 2> 66425 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[32 (1435451216507174912)]} 0 5
[junit4:junit4] 2> 66426 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[32]} 0 8
[junit4:junit4] 2> 66429 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[33 (1435451216515563520)]} 0 0
[junit4:junit4] 2> 66436 T114 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[33 (1435451216518709248)]} 0 1
[junit4:junit4] 2> 66436 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[33 (1435451216518709248)]} 0 4
[junit4:junit4] 2> 66439 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[34 (1435451216526049280)]} 0 0
[junit4:junit4] 2> 66445 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[34 (1435451216529195008)]} 0 1
[junit4:junit4] 2> 66446 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[34 (1435451216529195008)]} 0 4
[junit4:junit4] 2> 66449 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[35 (1435451216535486464)]} 0 1
[junit4:junit4] 2> 66457 T133 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[35 (1435451216541777920)]} 0 1
[junit4:junit4] 2> 66458 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[35 (1435451216541777920)]} 0 4
[junit4:junit4] 2> 66458 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[35]} 0 7
[junit4:junit4] 2> 66461 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[36 (1435451216549117952)]} 0 0
[junit4:junit4] 2> 66467 T131 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[36 (1435451216552263680)]} 0 1
[junit4:junit4] 2> 66468 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[36 (1435451216552263680)]} 0 4
[junit4:junit4] 2> 66470 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[37 (1435451216558555136)]} 0 0
[junit4:junit4] 2> 66479 T115 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[37 (1435451216564846592)]} 0 1
[junit4:junit4] 2> 66480 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[37 (1435451216564846592)]} 0 5
[junit4:junit4] 2> 66480 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[37]} 0 7
[junit4:junit4] 2> 66484 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[38 (1435451216572186624)]} 0 1
[junit4:junit4] 2> 66490 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[38 (1435451216575332352)]} 0 1
[junit4:junit4] 2> 66490 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[38 (1435451216575332352)]} 0 4
[junit4:junit4] 2> 66493 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[39 (1435451216582672384)]} 0 0
[junit4:junit4] 2> 66499 T117 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[39 (1435451216585818112)]} 0 0
[junit4:junit4] 2> 66500 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[39 (1435451216585818112)]} 0 4
[junit4:junit4] 2> 66504 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[40 (1435451216593158144)]} 0 1
[junit4:junit4] 2> 66510 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[40 (1435451216597352448)]} 0 0
[junit4:junit4] 2> 66511 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[40 (1435451216597352448)]} 0 5
[junit4:junit4] 2> 66514 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[41 (1435451216604692480)]} 0 0
[junit4:junit4] 2> 66521 T133 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[41 (1435451216607838208)]} 0 1
[junit4:junit4] 2> 66522 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[41 (1435451216607838208)]} 0 5
[junit4:junit4] 2> 66526 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[42 (1435451216616226816)]} 0 1
[junit4:junit4] 2> 66536 T131 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[42 (1435451216623566848)]} 0 1
[junit4:junit4] 2> 66537 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[42 (1435451216623566848)]} 0 5
[junit4:junit4] 2> 66538 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[42]} 0 9
[junit4:junit4] 2> 66542 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[43 (1435451216633004032)]} 0 1
[junit4:junit4] 2> 66549 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[43 (1435451216638246912)]} 0 0
[junit4:junit4] 2> 66550 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[43 (1435451216638246912)]} 0 5
[junit4:junit4] 2> 66553 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[44 (1435451216645586944)]} 0 0
[junit4:junit4] 2> 66562 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[44 (1435451216650829824)]} 0 1
[junit4:junit4] 2> 66562 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[44 (1435451216650829824)]} 0 4
[junit4:junit4] 2> 66563 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[44]} 0 7
[junit4:junit4] 2> 66567 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[45 (1435451216659218432)]} 0 1
[junit4:junit4] 2> 66573 T116 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[45 (1435451216663412736)]} 0 1
[junit4:junit4] 2> 66573 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[45 (1435451216663412736)]} 0 4
[junit4:junit4] 2> 66577 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[46 (1435451216669704192)]} 0 1
[junit4:junit4] 2> 66586 T133 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[46 (1435451216675995648)]} 0 1
[junit4:junit4] 2> 66586 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[46 (1435451216675995648)]} 0 4
[junit4:junit4] 2> 66587 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[46]} 0 8
[junit4:junit4] 2> 66590 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[47 (1435451216684384256)]} 0 0
[junit4:junit4] 2> 66596 T131 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[47 (1435451216687529984)]} 0 1
[junit4:junit4] 2> 66596 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[47 (1435451216687529984)]} 0 3
[junit4:junit4] 2> 66600 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[48 (1435451216693821440)]} 0 1
[junit4:junit4] 2> 66606 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[48 (1435451216696967168)]} 0 1
[junit4:junit4] 2> 66606 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[48 (1435451216696967168)]} 0 4
[junit4:junit4] 2> 66610 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[49 (1435451216704307200)]} 0 1
[junit4:junit4] 2> 66619 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[49 (1435451216710598656)]} 0 1
[junit4:junit4] 2> 66619 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[49 (1435451216710598656)]} 0 4
[junit4:junit4] 2> 66620 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[49]} 0 7
[junit4:junit4] 2> 66623 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[50 (1435451216718987264)]} 0 0
[junit4:junit4] 2> 66632 T133 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[50 (1435451216725278720)]} 0 1
[junit4:junit4] 2> 66633 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[50 (1435451216725278720)]} 0 5
[junit4:junit4] 2> 66634 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[50]} 0 8
[junit4:junit4] 2> 66637 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[51 (1435451216732618752)]} 0 1
[junit4:junit4] 2> 66644 T131 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[51 (1435451216737861632)]} 0 0
[junit4:junit4] 2> 66645 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[51 (1435451216737861632)]} 0 4
[junit4:junit4] 2> 66646 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[51]} 0 7
[junit4:junit4] 2> 66649 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[52 (1435451216745201664)]} 0 1
[junit4:junit4] 2> 66654 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[52 (1435451216748347392)]} 0 1
[junit4:junit4] 2> 66655 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[52 (1435451216748347392)]} 0 4
[junit4:junit4] 2> 66658 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[53 (1435451216754638848)]} 0 1
[junit4:junit4] 2> 66663 T114 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[53 (1435451216757784576)]} 0 0
[junit4:junit4] 2> 66664 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[53 (1435451216757784576)]} 0 4
[junit4:junit4] 2> 66667 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[54 (1435451216764076032)]} 0 1
[junit4:junit4] 2> 66675 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[54 (1435451216770367488)]} 0 1
[junit4:junit4] 2> 66675 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[54 (1435451216770367488)]} 0 4
[junit4:junit4] 2> 66676 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[54]} 0 7
[junit4:junit4] 2> 66679 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[55 (1435451216777707520)]} 0 1
[junit4:junit4] 2> 66685 T133 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[55 (1435451216780853248)]} 0 0
[junit4:junit4] 2> 66686 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[55 (1435451216780853248)]} 0 4
[junit4:junit4] 2> 66689 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[56 (1435451216787144704)]} 0 1
[junit4:junit4] 2> 66695 T115 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[56 (1435451216791339008)]} 0 1
[junit4:junit4] 2> 66696 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[56 (1435451216791339008)]} 0 5
[junit4:junit4] 2> 66699 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[57 (1435451216797630464)]} 0 1
[junit4:junit4] 2> 66707 T116 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[57 (1435451216803921920)]} 0 1
[junit4:junit4] 2> 66708 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[57 (1435451216803921920)]} 0 4
[junit4:junit4] 2> 66708 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[57]} 0 7
[junit4:junit4] 2> 66712 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[58 (1435451216811261952)]} 0 1
[junit4:junit4] 2> 66720 T114 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[58 (1435451216817553408)]} 0 1
[junit4:junit4] 2> 66721 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[58 (1435451216817553408)]} 0 4
[junit4:junit4] 2> 66722 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[58]} 0 8
[junit4:junit4] 2> 66725 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[59 (1435451216824893440)]} 0 1
[junit4:junit4] 2> 66733 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[59 (1435451216831184896)]} 0 1
[junit4:junit4] 2> 66734 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[59 (1435451216831184896)]} 0 4
[junit4:junit4] 2> 66734 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[59]} 0 7
[junit4:junit4] 2> 66737 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[60 (1435451216838524928)]} 0 0
[junit4:junit4] 2> 66743 T117 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[60 (1435451216841670656)]} 0 1
[junit4:junit4] 2> 66744 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[60 (1435451216841670656)]} 0 4
[junit4:junit4] 2> 66746 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[61 (1435451216847962112)]} 0 0
[junit4:junit4] 2> 66754 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[61 (1435451216853204992)]} 0 1
[junit4:junit4] 2> 66755 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[61 (1435451216853204992)]} 0 4
[junit4:junit4] 2> 66755 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[61]} 0 6
[junit4:junit4] 2> 66758 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[62 (1435451216860545024)]} 0 1
[junit4:junit4] 2> 66766 T115 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[62 (1435451216865787904)]} 0 1
[junit4:junit4] 2> 66767 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[62 (1435451216865787904)]} 0 5
[junit4:junit4] 2> 66767 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[62]} 0 7
[junit4:junit4] 2> 66770 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[63 (1435451216873127936)]} 0 1
[junit4:junit4] 2> 66778 T131 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[63 (1435451216878370816)]} 0 1
[junit4:junit4] 2> 66779 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[63 (1435451216878370816)]} 0 4
[junit4:junit4] 2> 66779 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[63]} 0 7
[junit4:junit4] 2> 66782 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[64 (1435451216885710848)]} 0 0
[junit4:junit4] 2> 66790 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[64 (1435451216890953728)]} 0 0
[junit4:junit4] 2> 66791 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[64 (1435451216890953728)]} 0 4
[junit4:junit4] 2> 66792 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[64]} 0 7
[junit4:junit4] 2> 66795 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[65 (1435451216898293760)]} 0 1
[junit4:junit4] 2> 66800 T133 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[65 (1435451216901439488)]} 0 0
[junit4:junit4] 2> 66801 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[65 (1435451216901439488)]} 0 4
[junit4:junit4] 2> 66804 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[66 (1435451216908779520)]} 0 0
[junit4:junit4] 2> 66810 T134 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[66 (1435451216911925248)]} 0 0
[junit4:junit4] 2> 66811 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[66 (1435451216911925248)]} 0 4
[junit4:junit4] 2> 66814 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[67 (1435451216919265280)]} 0 0
[junit4:junit4] 2> 66822 T116 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[67 (1435451216924508160)]} 0 0
[junit4:junit4] 2> 66823 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[67 (1435451216924508160)]} 0 4
[junit4:junit4] 2> 66824 T101 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[67]} 0 7
[junit4:junit4] 2> 66827 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[68 (1435451216931848192)]} 0 1
[junit4:junit4] 2> 66833 T114 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[68 (1435451216936042496)]} 0 1
[junit4:junit4] 2> 66834 T82 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[68 (1435451216936042496)]} 0 5
[junit4:junit4] 2> 66838 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[69 (1435451216943382528)]} 0 1
[junit4:junit4] 2> 66845 T117 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[69 (1435451216947576832)]} 0 0
[junit4:junit4] 2> 66846 T83 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[69 (1435451216947576832)]} 0 5
[junit4:junit4] 2> 66849 T65 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[70 (1435451216954916864)]} 0 1
[junit4:junit4] 2> 66857 T131 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[70 (1435451216961208320)]} 0 0
[junit4:junit4] 2> 66858 T98 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[70 (1435451216961208320)]} 0 4
[junit4:junit4] 2> 66859 T85 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[70]} 0 8
[junit4:junit4] 2> 66862 T63 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[71 (1435451216969596928)]} 0 1
[junit4:junit4] 2> 66868 T115 C3 P54815 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[71 (1435451216972742656)]} 0 1
[junit4:junit4] 2> 66869 T84 C5 P43614 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[71 (1435451216972742656)]} 0 4
[junit4:junit4] 2> 66872 T62 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[72 (1435451216980082688)]} 0 1
[junit4:junit4] 2> 66878 T132 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[72 (1435451216983228416)]} 0 1
[junit4:junit4] 2> 66879 T99 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[72 (1435451216983228416)]} 0 3
[junit4:junit4] 2> 66882 T64 C7 P53328 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[73 (1435451216989519872)]} 0 1
[junit4:junit4] 2> 66889 T133 C4 P42384 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:51901/collection1/} {add=[73 (1435451216994762752)]} 0 0
[junit4:junit4] 2> 66890 T100 C6 P51901 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:43614/collection1/} {add=[73 (1435451216994762752)]} 0 4
[junit4:junit4] 2> 66891 T82 C5 P
[...truncated too long message...]
seer.start Overseer (id=89715699247742988-127.0.0.1:42384_-n_0000000004) starting
[junit4:junit4] 2> 232326 T138 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> 232326 T164 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 232329 T138 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4:junit4] 2> 232330 T163 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 232332 T163 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 232333 T163 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:54815_",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54815"}
[junit4:junit4] 2> 232337 T163 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "node_name":"127.0.0.1:54815_",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54815"}
[junit4:junit4] 2> 232344 T138 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> 232344 T45 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 232397 T45 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 42384
[junit4:junit4] 2> 232397 T45 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=2007035963
[junit4:junit4] 2> 232526 T89 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 232527 T89 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 233400 T45 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 233400 T45 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 233402 T45 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@2aec26a5
[junit4:junit4] 2> 233408 T45 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=4,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=836,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 233409 T45 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 233409 T45 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 233409 T45 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 233411 T45 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 233411 T45 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 233411 T45 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4;done=false>>]
[junit4:junit4] 2> 233412 T45 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4
[junit4:junit4] 2> 233412 T45 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/index;done=false>>]
[junit4:junit4] 2> 233412 T45 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368952930300/jetty4/index
[junit4:junit4] 2> 233413 T163 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89715699247742988-127.0.0.1:42384_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 233436 T45 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 233491 T45 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 233494 T45 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:33172 33172
[junit4:junit4] 2> 233496 T45 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 53328
[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-1368952930300 FAILED !!!!!
[junit4:junit4] 2> 233497 T45 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 233497 T45 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:33172 33172
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeyShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=D70B922181ED5948 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_EG -Dtests.timezone=America/Adak -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 194s J0 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard2 is not consistent. Got 48 from http://127.0.0.1:43614/collection1lastClient and got 47 from http://127.0.0.1:54815/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([D70B922181ED5948:56ED1C39F6B23974]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:110)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> 233526 T45 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 194457 T44 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 233618 T121 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 233618 T121 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> 233618 T121 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 234714 T138 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 234714 T138 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> 234714 T138 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=SimpleText), _version_=Pulsing41(freqCutoff=12 minBlockSize=14 maxBlockSize=78)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=ar_EG, timezone=America/Adak
[junit4:junit4] 2> NOTE: Linux 3.2.0-41-generic amd64/Oracle Corporation 1.8.0-ea (64-bit)/cpus=8,threads=2,free=64446824,total=126484480
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestStressRecovery, TestPseudoReturnFields, OverseerCollectionProcessorTest, TestWriterPerf, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J0 in 195.77s, 1 test, 1 failure <<< FAILURES!
[...truncated 840 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:377: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:357: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1240: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:884: There were test failures: 295 suites, 1231 tests, 1 failure, 16 ignored (7 assumptions)
Total time: 37 minutes 32 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.8.0-ea-b89 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure