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/23 22:13:04 UTC
[JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.7.0_21) - Build # 5735
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5735/
Java: 64bit/jdk1.7.0_21 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Wrong doc count on shard1_0 expected:<393> but was:<392>
Stack Trace:
java.lang.AssertionError: Wrong doc count on shard1_0 expected:<393> but was:<392>
at __randomizedtesting.SeedInfo.seed([92DF274D78CC583E:1339A9550F933802]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(ShardSplitTest.java:166)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:155)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 10191 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 1065582 T3244 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 1065587 T3244 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeyShardSplitTest-1369339778233
[junit4:junit4] 2> 1065587 T3244 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1065588 T3245 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1065688 T3244 oasc.ZkTestServer.run start zk server on port:58632
[junit4:junit4] 2> 1065689 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1065692 T3251 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6da368c9 name:ZooKeeperConnection Watcher:127.0.0.1:58632 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1065693 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1065693 T3244 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1065697 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1065699 T3253 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@151c998 name:ZooKeeperConnection Watcher:127.0.0.1:58632/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1065699 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1065699 T3244 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1065702 T3244 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1065704 T3244 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1065705 T3244 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1065708 T3244 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1065708 T3244 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1065713 T3244 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1065713 T3244 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1065717 T3244 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1065717 T3244 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1065719 T3244 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1065720 T3244 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1065722 T3244 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1065722 T3244 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1065725 T3244 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1065725 T3244 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1065727 T3244 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1065728 T3244 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1065730 T3244 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1065730 T3244 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1065732 T3244 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1065732 T3244 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1065790 T3244 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1065793 T3244 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:44638
[junit4:junit4] 2> 1065793 T3244 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1065794 T3244 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1065794 T3244 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369339778381
[junit4:junit4] 2> 1065794 T3244 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369339778381/solr.xml
[junit4:junit4] 2> 1065795 T3244 oasc.CoreContainer.<init> New CoreContainer 19242953
[junit4:junit4] 2> 1065795 T3244 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369339778381/'
[junit4:junit4] 2> 1065795 T3244 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369339778381/'
[junit4:junit4] 2> 1065835 T3244 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1065836 T3244 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1065836 T3244 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1065836 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1065837 T3244 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1065837 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1065837 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1065838 T3244 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1065838 T3244 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1065838 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1065841 T3244 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1065842 T3244 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58632/solr
[junit4:junit4] 2> 1065842 T3244 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1065843 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1065844 T3264 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6dbcd8a9 name:ZooKeeperConnection Watcher:127.0.0.1:58632 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1065845 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1065846 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1065849 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1065850 T3266 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@104455e1 name:ZooKeeperConnection Watcher:127.0.0.1:58632/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1065850 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1065852 T3244 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1065855 T3244 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1065858 T3244 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1065859 T3244 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44638_
[junit4:junit4] 2> 1065860 T3244 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44638_
[junit4:junit4] 2> 1065861 T3244 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1065864 T3244 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1065866 T3244 oasc.Overseer.start Overseer (id=89741051706474499-127.0.0.1:44638_-n_0000000000) starting
[junit4:junit4] 2> 1065868 T3244 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1065870 T3268 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1065870 T3244 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1065872 T3244 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1065874 T3244 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1065876 T3267 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1065879 T3269 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369339778381/collection1
[junit4:junit4] 2> 1065879 T3269 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1065880 T3269 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1065880 T3269 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1065882 T3269 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369339778381/collection1/'
[junit4:junit4] 2> 1065883 T3269 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369339778381/collection1/lib/README' to classloader
[junit4:junit4] 2> 1065883 T3269 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369339778381/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1065912 T3269 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1065946 T3269 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1065948 T3269 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1065951 T3269 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1066220 T3269 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1066222 T3269 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1066223 T3269 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1066226 T3269 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1066245 T3269 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1066245 T3269 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369339778381/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/control/data/
[junit4:junit4] 2> 1066246 T3269 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f8551ae
[junit4:junit4] 2> 1066246 T3269 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1066246 T3269 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/control/data
[junit4:junit4] 2> 1066247 T3269 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/control/data/index/
[junit4:junit4] 2> 1066247 T3269 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1066247 T3269 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/control/data/index
[junit4:junit4] 2> 1066248 T3269 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@8302da3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15351555)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1066249 T3269 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1066250 T3269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1066250 T3269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1066251 T3269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1066251 T3269 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1066251 T3269 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1066252 T3269 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1066252 T3269 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1066252 T3269 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1066252 T3269 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1066254 T3269 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1066256 T3269 oass.SolrIndexSearcher.<init> Opening Searcher@55c89179 main
[junit4:junit4] 2> 1066257 T3269 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/control/data/tlog
[junit4:junit4] 2> 1066257 T3269 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1066257 T3269 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1066260 T3270 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@55c89179 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1066261 T3269 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1066261 T3269 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1067380 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1067381 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44638_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44638"}
[junit4:junit4] 2> 1067381 T3267 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1067381 T3267 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1067384 T3266 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> 1068265 T3269 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1068266 T3269 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44638 collection:control_collection shard:shard1
[junit4:junit4] 2> 1068267 T3269 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1068273 T3269 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1068275 T3269 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1068276 T3269 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1068276 T3269 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:44638/collection1/
[junit4:junit4] 2> 1068276 T3269 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1068276 T3269 oasc.SyncStrategy.syncToMe http://127.0.0.1:44638/collection1/ has no replicas
[junit4:junit4] 2> 1068276 T3269 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:44638/collection1/
[junit4:junit4] 2> 1068276 T3269 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1068889 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1068979 T3266 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> 1069033 T3269 oasc.ZkController.register We are http://127.0.0.1:44638/collection1/ and leader is http://127.0.0.1:44638/collection1/
[junit4:junit4] 2> 1069033 T3269 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44638
[junit4:junit4] 2> 1069033 T3269 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1069034 T3269 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1069034 T3269 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1069035 T3269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1069036 T3244 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1069037 T3244 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1069037 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1069040 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1069041 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1069048 T3273 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@158628f5 name:ZooKeeperConnection Watcher:127.0.0.1:58632/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1069049 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1069050 T3244 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1069054 T3244 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1069125 T3244 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1069127 T3244 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52097
[junit4:junit4] 2> 1069128 T3244 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1069128 T3244 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1069129 T3244 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369339781700
[junit4:junit4] 2> 1069130 T3244 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369339781700/solr.xml
[junit4:junit4] 2> 1069130 T3244 oasc.CoreContainer.<init> New CoreContainer 1636988162
[junit4:junit4] 2> 1069131 T3244 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369339781700/'
[junit4:junit4] 2> 1069132 T3244 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369339781700/'
[junit4:junit4] 2> 1069181 T3244 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1069181 T3244 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1069182 T3244 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1069182 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1069182 T3244 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1069182 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1069183 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1069183 T3244 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1069183 T3244 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1069184 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1069186 T3244 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1069186 T3244 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58632/solr
[junit4:junit4] 2> 1069187 T3244 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1069188 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1069189 T3284 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2e5d3d41 name:ZooKeeperConnection Watcher:127.0.0.1:58632 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1069190 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1069193 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1069197 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1069199 T3286 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d15f173 name:ZooKeeperConnection Watcher:127.0.0.1:58632/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1069199 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1069205 T3244 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1070209 T3244 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52097_
[junit4:junit4] 2> 1070212 T3244 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52097_
[junit4:junit4] 2> 1070218 T3273 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1070218 T3286 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1070218 T3266 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1070219 T3266 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> 1070226 T3287 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369339781700/collection1
[junit4:junit4] 2> 1070227 T3287 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1070228 T3287 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1070228 T3287 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1070230 T3287 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369339781700/collection1/'
[junit4:junit4] 2> 1070231 T3287 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369339781700/collection1/lib/README' to classloader
[junit4:junit4] 2> 1070232 T3287 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369339781700/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1070263 T3287 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1070291 T3287 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1070293 T3287 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1070296 T3287 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1070486 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1070487 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:44638__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44638_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44638"}
[junit4:junit4] 2> 1070490 T3286 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> 1070490 T3273 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> 1070491 T3266 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> 1070551 T3287 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1070553 T3287 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1070554 T3287 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1070557 T3287 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1070579 T3287 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1070579 T3287 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369339781700/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty1/
[junit4:junit4] 2> 1070580 T3287 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f8551ae
[junit4:junit4] 2> 1070580 T3287 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1070580 T3287 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty1
[junit4:junit4] 2> 1070580 T3287 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty1/index/
[junit4:junit4] 2> 1070581 T3287 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1070581 T3287 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty1/index
[junit4:junit4] 2> 1070583 T3287 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5f6d7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@504f78b6)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1070583 T3287 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1070585 T3287 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1070585 T3287 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1070586 T3287 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1070586 T3287 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1070587 T3287 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1070587 T3287 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1070587 T3287 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1070588 T3287 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1070588 T3287 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1070590 T3287 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1070593 T3287 oass.SolrIndexSearcher.<init> Opening Searcher@71dad85f main
[junit4:junit4] 2> 1070593 T3287 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty1/tlog
[junit4:junit4] 2> 1070593 T3287 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1070594 T3287 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1070597 T3288 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@71dad85f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1070598 T3287 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1070598 T3287 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1071995 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1071996 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:52097_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52097"}
[junit4:junit4] 2> 1071996 T3267 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 1071996 T3267 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1072001 T3286 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> 1072001 T3266 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> 1072001 T3273 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> 1072599 T3287 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1072600 T3287 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52097 collection:collection1 shard:shard1
[junit4:junit4] 2> 1072601 T3287 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1072606 T3287 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1072608 T3287 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1072608 T3287 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1072608 T3287 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52097/collection1/
[junit4:junit4] 2> 1072608 T3287 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1072609 T3287 oasc.SyncStrategy.syncToMe http://127.0.0.1:52097/collection1/ has no replicas
[junit4:junit4] 2> 1072609 T3287 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52097/collection1/
[junit4:junit4] 2> 1072609 T3287 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1073505 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1073512 T3286 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> 1073512 T3273 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> 1073512 T3266 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> 1073516 T3287 oasc.ZkController.register We are http://127.0.0.1:52097/collection1/ and leader is http://127.0.0.1:52097/collection1/
[junit4:junit4] 2> 1073516 T3287 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52097
[junit4:junit4] 2> 1073516 T3287 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1073516 T3287 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1073516 T3287 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1073518 T3287 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1073519 T3244 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1073520 T3244 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1073520 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1073579 T3244 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1073581 T3244 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:43386
[junit4:junit4] 2> 1073582 T3244 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1073582 T3244 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1073583 T3244 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369339786169
[junit4:junit4] 2> 1073583 T3244 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369339786169/solr.xml
[junit4:junit4] 2> 1073583 T3244 oasc.CoreContainer.<init> New CoreContainer 455411474
[junit4:junit4] 2> 1073584 T3244 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369339786169/'
[junit4:junit4] 2> 1073584 T3244 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369339786169/'
[junit4:junit4] 2> 1073622 T3244 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1073623 T3244 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1073623 T3244 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1073623 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1073624 T3244 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1073624 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1073624 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1073625 T3244 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1073625 T3244 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1073625 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1073628 T3244 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1073628 T3244 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58632/solr
[junit4:junit4] 2> 1073628 T3244 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1073629 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1073631 T3300 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@43818a59 name:ZooKeeperConnection Watcher:127.0.0.1:58632 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1073632 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1073633 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1073636 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1073637 T3302 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4480567a name:ZooKeeperConnection Watcher:127.0.0.1:58632/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1073637 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1073640 T3244 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1074643 T3244 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43386_
[junit4:junit4] 2> 1074646 T3244 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43386_
[junit4:junit4] 2> 1074651 T3266 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1074651 T3286 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1074651 T3286 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> 1074651 T3273 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1074651 T3302 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1074651 T3266 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> 1074652 T3273 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> 1074656 T3303 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369339786169/collection1
[junit4:junit4] 2> 1074657 T3303 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1074657 T3303 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1074658 T3303 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1074659 T3303 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369339786169/collection1/'
[junit4:junit4] 2> 1074659 T3303 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369339786169/collection1/lib/README' to classloader
[junit4:junit4] 2> 1074660 T3303 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369339786169/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1074690 T3303 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1074717 T3303 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1074719 T3303 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1074722 T3303 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1074989 T3303 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1074991 T3303 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1074993 T3303 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1074996 T3303 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1075014 T3303 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1075015 T3303 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369339786169/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty2/
[junit4:junit4] 2> 1075015 T3303 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f8551ae
[junit4:junit4] 2> 1075015 T3303 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1075016 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1075016 T3303 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty2
[junit4:junit4] 2> 1075016 T3303 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty2/index/
[junit4:junit4] 2> 1075016 T3303 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1075016 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:52097__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:52097_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52097"}
[junit4:junit4] 2> 1075017 T3303 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty2/index
[junit4:junit4] 2> 1075018 T3303 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6ae26cba lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b45343)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1075019 T3303 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1075020 T3302 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> 1075020 T3266 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> 1075020 T3273 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> 1075020 T3286 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> 1075021 T3303 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1075021 T3303 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1075022 T3303 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1075022 T3303 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1075023 T3303 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1075023 T3303 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1075023 T3303 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1075024 T3303 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1075024 T3303 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1075026 T3303 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1075028 T3303 oass.SolrIndexSearcher.<init> Opening Searcher@499dae3f main
[junit4:junit4] 2> 1075028 T3303 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty2/tlog
[junit4:junit4] 2> 1075029 T3303 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1075029 T3303 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1075032 T3304 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@499dae3f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1075033 T3303 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1075034 T3303 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1076524 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1076525 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:43386_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43386"}
[junit4:junit4] 2> 1076525 T3267 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1076525 T3267 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1076530 T3302 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> 1076530 T3286 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> 1076530 T3273 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> 1076530 T3266 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> 1077035 T3303 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1077036 T3303 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43386 collection:collection1 shard:shard2
[junit4:junit4] 2> 1077036 T3303 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1077042 T3303 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1077045 T3303 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1077045 T3303 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1077045 T3303 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43386/collection1/
[junit4:junit4] 2> 1077045 T3303 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1077046 T3303 oasc.SyncStrategy.syncToMe http://127.0.0.1:43386/collection1/ has no replicas
[junit4:junit4] 2> 1077046 T3303 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43386/collection1/
[junit4:junit4] 2> 1077046 T3303 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1078034 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1078041 T3302 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> 1078041 T3273 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> 1078041 T3286 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> 1078041 T3266 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> 1078053 T3303 oasc.ZkController.register We are http://127.0.0.1:43386/collection1/ and leader is http://127.0.0.1:43386/collection1/
[junit4:junit4] 2> 1078054 T3303 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43386
[junit4:junit4] 2> 1078054 T3303 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1078054 T3303 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1078054 T3303 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1078056 T3303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1078057 T3244 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1078057 T3244 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1078058 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1078113 T3244 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1078115 T3244 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40946
[junit4:junit4] 2> 1078116 T3244 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1078117 T3244 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1078117 T3244 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369339790706
[junit4:junit4] 2> 1078117 T3244 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369339790706/solr.xml
[junit4:junit4] 2> 1078118 T3244 oasc.CoreContainer.<init> New CoreContainer 838322931
[junit4:junit4] 2> 1078118 T3244 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369339790706/'
[junit4:junit4] 2> 1078118 T3244 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369339790706/'
[junit4:junit4] 2> 1078156 T3244 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1078157 T3244 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1078157 T3244 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1078157 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1078158 T3244 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1078158 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1078158 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1078159 T3244 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1078159 T3244 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1078159 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1078162 T3244 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1078162 T3244 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58632/solr
[junit4:junit4] 2> 1078163 T3244 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1078163 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1078165 T3316 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f4edb28 name:ZooKeeperConnection Watcher:127.0.0.1:58632 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1078165 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1078167 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1078170 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1078171 T3318 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@200b7f88 name:ZooKeeperConnection Watcher:127.0.0.1:58632/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1078171 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1078175 T3244 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1079178 T3244 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40946_
[junit4:junit4] 2> 1079180 T3244 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40946_
[junit4:junit4] 2> 1079183 T3318 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1079183 T3302 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1079183 T3266 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1079183 T3266 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> 1079183 T3302 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> 1079183 T3286 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1079183 T3273 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1079184 T3286 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> 1079184 T3273 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> 1079188 T3319 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369339790706/collection1
[junit4:junit4] 2> 1079188 T3319 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1079189 T3319 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1079189 T3319 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1079191 T3319 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369339790706/collection1/'
[junit4:junit4] 2> 1079191 T3319 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369339790706/collection1/lib/README' to classloader
[junit4:junit4] 2> 1079191 T3319 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369339790706/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1079214 T3319 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1079241 T3319 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1079243 T3319 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1079246 T3319 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1079529 T3319 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1079531 T3319 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1079532 T3319 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1079535 T3319 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1079546 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1079547 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43386__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:43386_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43386"}
[junit4:junit4] 2> 1079550 T3318 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> 1079550 T3302 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> 1079550 T3273 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> 1079550 T3286 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> 1079551 T3266 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> 1079555 T3319 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1079555 T3319 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369339790706/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty3/
[junit4:junit4] 2> 1079555 T3319 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f8551ae
[junit4:junit4] 2> 1079556 T3319 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1079556 T3319 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty3
[junit4:junit4] 2> 1079556 T3319 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty3/index/
[junit4:junit4] 2> 1079557 T3319 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1079557 T3319 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty3/index
[junit4:junit4] 2> 1079558 T3319 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@38855642 lockFactory=org.apache.lucene.store.NativeFSLockFactory@12dd9198)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1079559 T3319 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1079560 T3319 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1079560 T3319 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1079561 T3319 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1079561 T3319 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1079562 T3319 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1079562 T3319 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1079562 T3319 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1079562 T3319 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1079563 T3319 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1079565 T3319 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1079567 T3319 oass.SolrIndexSearcher.<init> Opening Searcher@7dbc4958 main
[junit4:junit4] 2> 1079567 T3319 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty3/tlog
[junit4:junit4] 2> 1079568 T3319 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1079568 T3319 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1079571 T3320 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7dbc4958 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1079571 T3319 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1079572 T3319 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1081055 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1081056 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:40946_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40946"}
[junit4:junit4] 2> 1081056 T3267 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1081056 T3267 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1081109 T3318 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> 1081110 T3273 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> 1081109 T3266 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> 1081109 T3286 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> 1081109 T3302 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> 1081573 T3319 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1081573 T3319 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40946 collection:collection1 shard:shard1
[junit4:junit4] 2> 1081576 T3319 oasc.ZkController.register We are http://127.0.0.1:40946/collection1/ and leader is http://127.0.0.1:52097/collection1/
[junit4:junit4] 2> 1081577 T3319 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40946
[junit4:junit4] 2> 1081577 T3319 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1081577 T3319 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2761 name=collection1 org.apache.solr.core.SolrCore@b964b1a url=http://127.0.0.1:40946/collection1 node=127.0.0.1:40946_ C2761_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:40946_, base_url=http://127.0.0.1:40946}
[junit4:junit4] 2> 1081577 T3321 C2761 P40946 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1081578 T3321 C2761 P40946 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1081578 T3319 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1081578 T3321 C2761 P40946 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1081579 T3321 C2761 P40946 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1081579 T3244 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1081580 T3244 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1081580 T3321 C2761 P40946 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1081580 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1081585 T3279 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:40946__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1081640 T3244 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1081642 T3244 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:43402
[junit4:junit4] 2> 1081643 T3244 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1081644 T3244 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1081644 T3244 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369339794230
[junit4:junit4] 2> 1081644 T3244 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369339794230/solr.xml
[junit4:junit4] 2> 1081645 T3244 oasc.CoreContainer.<init> New CoreContainer 1015204724
[junit4:junit4] 2> 1081645 T3244 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369339794230/'
[junit4:junit4] 2> 1081645 T3244 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369339794230/'
[junit4:junit4] 2> 1081693 T3244 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1081694 T3244 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1081694 T3244 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1081694 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1081695 T3244 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1081695 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1081695 T3244 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1081696 T3244 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1081696 T3244 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1081696 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1081699 T3244 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1081700 T3244 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58632/solr
[junit4:junit4] 2> 1081700 T3244 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1081701 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1081702 T3333 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@51c9f06b name:ZooKeeperConnection Watcher:127.0.0.1:58632 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1081703 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1081705 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1081708 T3244 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1081709 T3335 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5b881730 name:ZooKeeperConnection Watcher:127.0.0.1:58632/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1081710 T3244 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1081714 T3244 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1082614 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1082615 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:40946__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:40946_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40946"}
[junit4:junit4] 2> 1082669 T3318 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> 1082670 T3335 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> 1082670 T3286 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> 1082669 T3273 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> 1082669 T3266 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> 1082669 T3302 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> 1082717 T3244 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43402_
[junit4:junit4] 2> 1082718 T3244 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43402_
[junit4:junit4] 2> 1082720 T3318 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> 1082720 T3302 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1082721 T3273 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1082721 T3335 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1082721 T3335 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> 1082721 T3286 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1082721 T3266 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1082722 T3266 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> 1082721 T3302 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> 1082721 T3286 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> 1082721 T3273 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> 1082722 T3318 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1082726 T3336 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369339794230/collection1
[junit4:junit4] 2> 1082726 T3336 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1082727 T3336 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1082727 T3336 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1082728 T3336 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369339794230/collection1/'
[junit4:junit4] 2> 1082729 T3336 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369339794230/collection1/lib/README' to classloader
[junit4:junit4] 2> 1082729 T3336 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369339794230/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1082752 T3336 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1082779 T3336 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1082781 T3336 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1082784 T3336 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1083062 T3336 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1083064 T3336 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1083065 T3336 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1083069 T3336 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1083085 T3336 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1083085 T3336 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369339794230/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty4/
[junit4:junit4] 2> 1083086 T3336 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f8551ae
[junit4:junit4] 2> 1083086 T3336 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1083086 T3336 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty4
[junit4:junit4] 2> 1083087 T3336 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty4/index/
[junit4:junit4] 2> 1083087 T3336 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1083087 T3336 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty4/index
[junit4:junit4] 2> 1083089 T3336 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@76662d0e lockFactory=org.apache.lucene.store.NativeFSLockFactory@515a209f)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1083089 T3336 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1083090 T3336 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1083091 T3336 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1083091 T3336 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1083091 T3336 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1083092 T3336 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1083092 T3336 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1083092 T3336 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1083093 T3336 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1083093 T3336 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1083095 T3336 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1083097 T3336 oass.SolrIndexSearcher.<init> Opening Searcher@720dc696 main
[junit4:junit4] 2> 1083098 T3336 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty4/tlog
[junit4:junit4] 2> 1083098 T3336 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1083098 T3336 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1083102 T3337 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@720dc696 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1083103 T3336 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1083103 T3336 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1083586 T3279 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:40946__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1083586 T3279 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:40946__collection1&state=recovering&nodeName=127.0.0.1:40946_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2001
[junit4:junit4] 2> 1084175 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1084176 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:43402_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43402"}
[junit4:junit4] 2> 1084176 T3267 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1084177 T3267 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1084180 T3302 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> 1084181 T3266 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> 1084181 T3286 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> 1084180 T3318 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> 1084180 T3335 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> 1084180 T3273 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> 1085105 T3336 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1085105 T3336 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43402 collection:collection1 shard:shard2
[junit4:junit4] 2> 1085121 T3336 oasc.ZkController.register We are http://127.0.0.1:43402/collection1/ and leader is http://127.0.0.1:43386/collection1/
[junit4:junit4] 2> 1085121 T3336 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43402
[junit4:junit4] 2> 1085121 T3336 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1085121 T3336 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2762 name=collection1 org.apache.solr.core.SolrCore@4f3b8158 url=http://127.0.0.1:43402/collection1 node=127.0.0.1:43402_ C2762_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:43402_, base_url=http://127.0.0.1:43402}
[junit4:junit4] 2> 1085122 T3338 C2762 P43402 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1085122 T3336 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1085123 T3338 C2762 P43402 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1085123 T3338 C2762 P43402 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1085123 T3338 C2762 P43402 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1085124 T3244 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1085125 T3244 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1085125 T3244 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1085125 T3338 C2762 P43402 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1085129 T3244 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1085129 T3295 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:43402__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1085130 T3244 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1085130 T3244 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1085131 T3244 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C2763 name=collection1 org.apache.solr.core.SolrCore@b964b1a url=http://127.0.0.1:40946/collection1 node=127.0.0.1:40946_ C2763_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:40946_, base_url=http://127.0.0.1:40946}
[junit4:junit4] 2> 1085587 T3321 C2763 P40946 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52097/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1085588 T3321 C2763 P40946 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40946 START replicas=[http://127.0.0.1:52097/collection1/] nUpdates=100
[junit4:junit4] 2> 1085588 T3321 C2763 P40946 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1085589 T3321 C2763 P40946 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1085589 T3321 C2763 P40946 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1085589 T3321 C2763 P40946 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1085589 T3321 C2763 P40946 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1085589 T3321 C2763 P40946 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52097/collection1/. core=collection1
[junit4:junit4] 2> 1085589 T3321 C2763 P40946 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2764 name=collection1 org.apache.solr.core.SolrCore@7d77b5ec url=http://127.0.0.1:52097/collection1 node=127.0.0.1:52097_ C2764_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52097_, base_url=http://127.0.0.1:52097, leader=true}
[junit4:junit4] 2> 1085595 T3279 C2764 P52097 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1085596 T3282 C2764 P52097 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1085597 T3282 C2764 P52097 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5f6d7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@504f78b6)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1085598 T3282 C2764 P52097 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1085598 T3282 C2764 P52097 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5f6d7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@504f78b6)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5f6d7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@504f78b6)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1085599 T3282 C2764 P52097 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1085599 T3282 C2764 P52097 oass.SolrIndexSearcher.<init> Opening Searcher@36b19318 realtime
[junit4:junit4] 2> 1085600 T3282 C2764 P52097 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1085602 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 1085603 T3321 C2763 P40946 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1085604 T3321 C2763 P40946 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1085606 T3281 C2764 P52097 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1085606 T3281 C2764 P52097 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 1085607 T3321 C2763 P40946 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1085607 T3321 C2763 P40946 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1085607 T3321 C2763 P40946 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1085610 T3279 C2764 P52097 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 1085610 T3321 C2763 P40946 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1085612 T3321 C2763 P40946 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty3/index.20130523100958257
[junit4:junit4] 2> 1085612 T3321 C2763 P40946 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@3f6a1f6b lockFactory=org.apache.lucene.store.NativeFSLockFactory@53781c9e) fullCopy=false
[junit4:junit4] 2> 1085614 T3282 C2764 P52097 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1085615 T3321 C2763 P40946 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1085616 T3321 C2763 P40946 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1085616 T3321 C2763 P40946 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1085617 T3321 C2763 P40946 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@38855642 lockFactory=org.apache.lucene.store.NativeFSLockFactory@12dd9198)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@38855642 lockFactory=org.apache.lucene.store.NativeFSLockFactory@12dd9198)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1085618 T3321 C2763 P40946 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1085618 T3321 C2763 P40946 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1085619 T3321 C2763 P40946 oass.SolrIndexSearcher.<init> Opening Searcher@7e0f2b1b main
[junit4:junit4] 2> 1085620 T3320 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7e0f2b1b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1085620 T3321 C2763 P40946 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty3/index.20130523100958257 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty3/index.20130523100958257;done=true>>]
[junit4:junit4] 2> 1085620 T3321 C2763 P40946 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty3/index.20130523100958257
[junit4:junit4] 2> 1085621 T3321 C2763 P40946 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty3/index.20130523100958257
[junit4:junit4] 2> 1085621 T3321 C2763 P40946 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1085621 T3321 C2763 P40946 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1085621 T3321 C2763 P40946 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1085622 T3321 C2763 P40946 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1085624 T3321 C2763 P40946 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1085685 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1085686 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43402__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:43402_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43402"}
[junit4:junit4] 2> 1085688 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:40946__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:40946_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40946"}
[junit4:junit4] 2> 1085691 T3318 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> 1085691 T3302 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> 1085691 T3273 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> 1085691 T3286 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> 1085691 T3335 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> 1085691 T3266 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> 1086130 T3295 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:43402__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 1086130 T3295 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:43402__collection1&state=recovering&nodeName=127.0.0.1:43402_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 1086132 T3244 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1087134 T3244 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C2762_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:43402_, base_url=http://127.0.0.1:43402}
[junit4:junit4] 2> 1088131 T3338 C2762 P43402 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:43386/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1088132 T3338 C2762 P43402 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:43402 START replicas=[http://127.0.0.1:43386/collection1/] nUpdates=100
[junit4:junit4] 2> 1088132 T3338 C2762 P43402 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1088132 T3338 C2762 P43402 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1088132 T3338 C2762 P43402 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1088133 T3338 C2762 P43402 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1088133 T3338 C2762 P43402 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1088133 T3338 C2762 P43402 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:43386/collection1/. core=collection1
[junit4:junit4] 2> 1088133 T3338 C2762 P43402 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1088136 T3244 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C2765 name=collection1 org.apache.solr.core.SolrCore@752788d3 url=http://127.0.0.1:43386/collection1 node=127.0.0.1:43386_ C2765_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43386_, base_url=http://127.0.0.1:43386, leader=true}
[junit4:junit4] 2> 1088138 T3295 C2765 P43386 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1088141 T3297 C2765 P43386 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1088142 T3297 C2765 P43386 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6ae26cba lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b45343)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1088142 T3297 C2765 P43386 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1088143 T3297 C2765 P43386 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6ae26cba lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b45343)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6ae26cba lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b45343)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1088143 T3297 C2765 P43386 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1088144 T3297 C2765 P43386 oass.SolrIndexSearcher.<init> Opening Searcher@35239e4f realtime
[junit4:junit4] 2> 1088144 T3297 C2765 P43386 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1088144 T3297 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 1088145 T3338 C2762 P43402 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1088145 T3338 C2762 P43402 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1088146 T3296 C2765 P43386 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1088147 T3296 C2765 P43386 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1088147 T3338 C2762 P43402 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1088147 T3338 C2762 P43402 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1088147 T3338 C2762 P43402 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1088149 T3295 C2765 P43386 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 1088150 T3338 C2762 P43402 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1088151 T3338 C2762 P43402 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty4/index.20130523101000796
[junit4:junit4] 2> 1088151 T3338 C2762 P43402 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@6578d347 lockFactory=org.apache.lucene.store.NativeFSLockFactory@25cc0569) fullCopy=false
[junit4:junit4] 2> 1088153 T3297 C2765 P43386 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1088154 T3338 C2762 P43402 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1088154 T3338 C2762 P43402 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1088154 T3338 C2762 P43402 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1088155 T3338 C2762 P43402 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@76662d0e lockFactory=org.apache.lucene.store.NativeFSLockFactory@515a209f)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@76662d0e lockFactory=org.apache.lucene.store.NativeFSLockFactory@515a209f)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1088155 T3338 C2762 P43402 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1088156 T3338 C2762 P43402 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1088156 T3338 C2762 P43402 oass.SolrIndexSearcher.<init> Opening Searcher@54581eef main
[junit4:junit4] 2> 1088157 T3337 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@54581eef main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1088157 T3338 C2762 P43402 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty4/index.20130523101000796 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty4/index.20130523101000796;done=true>>]
[junit4:junit4] 2> 1088157 T3338 C2762 P43402 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty4/index.20130523101000796
[junit4:junit4] 2> 1088157 T3338 C2762 P43402 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233/jetty4/index.20130523101000796
[junit4:junit4] 2> 1088157 T3338 C2762 P43402 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1088158 T3338 C2762 P43402 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1088158 T3338 C2762 P43402 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1088158 T3338 C2762 P43402 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1088180 T3338 C2762 P43402 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1088700 T3267 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1088702 T3267 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43402__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:43402_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43402"}
[junit4:junit4] 2> 1088750 T3266 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> 1088750 T3335 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> 1088750 T3302 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> 1088750 T3318 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> 1088750 T3286 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> 1088750 T3273 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> 1089138 T3244 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1089139 T3244 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C2766 name=collection1 org.apache.solr.core.SolrCore@5d3b9017 url=http://127.0.0.1:44638/collection1 node=127.0.0.1:44638_ C2766_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:44638_, base_url=http://127.0.0.1:44638, leader=true}
[junit4:junit4] 2> 1089145 T3262 C2766 P44638 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1089147 T3262 C2766 P44638 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@8302da3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15351555)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1089148 T3262 C2766 P44638 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1089149 T3262 C2766 P44638 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@8302da3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15351555)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@8302da3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15351555)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1089149 T3262 C2766 P44638 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1089150 T3262 C2766 P44638 oass.SolrIndexSearcher.<init> Opening Searcher@c76e6bc main
[junit4:junit4] 2> 1089150 T3262 C2766 P44638 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1089151 T3270 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c76e6bc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1089151 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 1089155 T3282 C2764 P52097 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1089155 T3282 C2764 P52097 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5f6d7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@504f78b6)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5f6d7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@504f78b6)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1089156 T3282 C2764 P52097 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1089156 T3282 C2764 P52097 oass.SolrIndexSearcher.<init> Opening Searcher@22b7bb40 main
[junit4:junit4] 2> 1089156 T3282 C2764 P52097 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1089157 T3288 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@22b7bb40 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1089157 T3282 C2764 P52097 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:40946/collection1/, StdNode: http://127.0.0.1:43386/collection1/, StdNode: http://127.0.0.1:43402/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 1089160 T3297 C2765 P43386 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1089161 T3297 C2765 P43386 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6ae26cba lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b45343)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6ae26cba lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b45343)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1089161 T3297 C2765 P43386 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1089162 T3297 C2765 P43386 oass.SolrIndexSearcher.<init> Opening Searcher@50520870 main
[junit4:junit4] 2> 1089162 T3297 C2765 P43386 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1089162 T3304 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@50520870 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1089163 T3297 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 2> C2762_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43402_, base_url=http://127.0.0.1:43402}
[junit4:junit4] 2> 1089163 T3328 C2762 P43402 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1089164 T3328 C2762 P43402 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@76662d0e lockFactory=org.apache.lucene.store.NativeFSLockFactory@515a209f)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@76662d0e lockFactory=org.apache.lucene.store.NativeFSLockFactory@515a209f)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1089165 T3328 C2762 P43402 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> C2763_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:40946_, base_url=http://127.0.0.1:40946}
[junit4:junit4] 2> 1089165 T3311 C2763 P40946 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1089165 T3328 C2762 P43402 oass.SolrIndexSearcher.<init> Opening Searcher@52f4ede main
[junit4:junit4] 2> 1089167 T3311 C2763 P40946 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@38855642 lockFactory=org.apache.lucene.store.NativeFSLockFactory@12dd9198)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@38855642 lockFactory=org.apache.lucene.store.NativeFSLockFactory@12dd9198)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1089167 T3337 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@52f4ede main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1089167 T3311 C2763 P40946 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1089167 T3328 C2762 P43402 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1089168 T3311 C2763 P40946 oass.SolrIndexSearcher.<init> Opening Searcher@405fafd7 main
[junit4:junit4] 2> 1089168 T3328 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 1089169 T3311 C2763 P40946 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1089169 T3320 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@405fafd7 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1089170 T3311 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 1089170 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> 1089171 T3244 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1089174 T3280 C2764 P52097 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 1089175 T3314 C2763 P40946 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1089177 T3296 C2765 P43386 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 1089178 T3329 C2762 P43402 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1091183 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435856854137700352)} 0 2
[junit4:junit4] 2> 1091189 T3313 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435856854142943232&update.from=http://127.0.0.1:52097/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435856854142943232)} 0 1
[junit4:junit4] 2> 1091191 T3329 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435856854145040384&update.from=http://127.0.0.1:43386/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435856854145040384)} 0 0
[junit4:junit4] 2> 1091192 T3298 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435856854145040384)} 0 4
[junit4:junit4] 2> 1091192 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435856854142943232)} 0 7
[junit4:junit4] 2> 1091195 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1435856854152380416)]} 0 0
[junit4:junit4] 2> 1091201 T3314 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1435856854155526144)]} 0 1
[junit4:junit4] 2> 1091201 T3281 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1435856854155526144)]} 0 3
[junit4:junit4] 2> 1091202 T3295 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 5
[junit4:junit4] 2> 1091204 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1435856854161817600)]} 0 0
[junit4:junit4] 2> 1091211 T3312 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1435856854167060480)]} 0 0
[junit4:junit4] 2> 1091212 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1435856854167060480)]} 0 4
[junit4:junit4] 2> 1091212 T3297 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1]} 0 5
[junit4:junit4] 2> 1091215 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1435856854173351936)]} 0 1
[junit4:junit4] 2> 1091220 T3331 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1435856854176497664)]} 0 0
[junit4:junit4] 2> 1091221 T3296 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1435856854176497664)]} 0 3
[junit4:junit4] 2> 1091224 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1435856854182789120)]} 0 1
[junit4:junit4] 2> 1091229 T3330 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1435856854184886272)]} 0 1
[junit4:junit4] 2> 1091230 T3298 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1435856854184886272)]} 0 4
[junit4:junit4] 2> 1091232 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1435856854191177728)]} 0 0
[junit4:junit4] 2> 1091238 T3311 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1435856854194323456)]} 0 1
[junit4:junit4] 2> 1091239 T3280 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1435856854194323456)]} 0 4
[junit4:junit4] 2> 1091241 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1435856854200614912)]} 0 0
[junit4:junit4] 2> 1091248 T3328 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1435856854205857792)]} 0 0
[junit4:junit4] 2> 1091249 T3295 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1435856854205857792)]} 0 3
[junit4:junit4] 2> 1091250 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5]} 0 6
[junit4:junit4] 2> 1091253 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1435856854212149248)]} 0 1
[junit4:junit4] 2> 1091258 T3329 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1435856854215294976)]} 0 1
[junit4:junit4] 2> 1091259 T3297 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1435856854215294976)]} 0 4
[junit4:junit4] 2> 1091261 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1435856854221586432)]} 0 0
[junit4:junit4] 2> 1091267 T3331 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1435856854225780736)]} 0 0
[junit4:junit4] 2> 1091267 T3296 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1435856854225780736)]} 0 2
[junit4:junit4] 2> 1091268 T3281 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7]} 0 5
[junit4:junit4] 2> 1091270 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1435856854231023616)]} 0 0
[junit4:junit4] 2> 1091275 T3313 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1435856854233120768)]} 0 1
[junit4:junit4] 2> 1091275 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1435856854233120768)]} 0 3
[junit4:junit4] 2> 1091277 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1435856854238363648)]} 0 0
[junit4:junit4] 2> 1091282 T3330 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1435856854241509376)]} 0 1
[junit4:junit4] 2> 1091283 T3298 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1435856854241509376)]} 0 4
[junit4:junit4] 2> 1091285 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1435856854246752256)]} 0 0
[junit4:junit4] 2> 1091292 T3314 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1435856854250946560)]} 0 1
[junit4:junit4] 2> 1091292 T3280 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1435856854250946560)]} 0 3
[junit4:junit4] 2> 1091293 T3295 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10]} 0 6
[junit4:junit4] 2> 1091295 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1435856854257238016)]} 0 0
[junit4:junit4] 2> 1091299 T3312 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1435856854259335168)]} 0 0
[junit4:junit4] 2> 1091300 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1435856854259335168)]} 0 3
[junit4:junit4] 2> 1091302 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1435856854264578048)]} 0 0
[junit4:junit4] 2> 1091307 T3311 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1435856854266675200)]} 0 1
[junit4:junit4] 2> 1091307 T3281 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1435856854266675200)]} 0 3
[junit4:junit4] 2> 1091310 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1435856854271918080)]} 0 1
[junit4:junit4] 2> 1091317 T3313 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1435856854277160960)]} 0 1
[junit4:junit4] 2> 1091318 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1435856854277160960)]} 0 4
[junit4:junit4] 2> 1091318 T3297 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13]} 0 6
[junit4:junit4] 2> 1091321 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1435856854284500992)]} 0 0
[junit4:junit4] 2> 1091327 T3314 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1435856854288695296)]} 0 0
[junit4:junit4] 2> 1091328 T3280 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1435856854288695296)]} 0 4
[junit4:junit4] 2> 1091330 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1435856854293938176)]} 0 0
[junit4:junit4] 2> 1091335 T3312 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1435856854297083904)]} 0 0
[junit4:junit4] 2> 1091336 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1435856854297083904)]} 0 3
[junit4:junit4] 2> 1091338 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1435856854302326784)]} 0 0
[junit4:junit4] 2> 1091346 T3311 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1435856854307569664)]} 0 1
[junit4:junit4] 2> 1091348 T3281 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1435856854307569664)]} 0 5
[junit4:junit4] 2> 1091350 T3296 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16]} 0 9
[junit4:junit4] 2> 1091354 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1435856854318055424)]} 0 1
[junit4:junit4] 2> 1091358 T3328 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1435856854321201152)]} 0 0
[junit4:junit4] 2> 1091359 T3298 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1435856854321201152)]} 0 3
[junit4:junit4] 2> 1091362 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1435856854327492608)]} 0 1
[junit4:junit4] 2> 1091368 T3329 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1435856854331686912)]} 0 0
[junit4:junit4] 2> 1091369 T3295 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1435856854331686912)]} 0 3
[junit4:junit4] 2> 1091369 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18]} 0 5
[junit4:junit4] 2> 1091372 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1435856854336929792)]} 0 1
[junit4:junit4] 2> 1091378 T3331 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1435856854342172672)]} 0 0
[junit4:junit4] 2> 1091379 T3297 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1435856854342172672)]} 0 3
[junit4:junit4] 2> 1091379 T3280 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19]} 0 5
[junit4:junit4] 2> 1091381 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1435856854347415552)]} 0 0
[junit4:junit4] 2> 1091386 T3313 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1435856854350561280)]} 0 0
[junit4:junit4] 2> 1091387 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1435856854350561280)]} 0 3
[junit4:junit4] 2> 1091389 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1435856854355804160)]} 0 0
[junit4:junit4] 2> 1091393 T3330 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1435856854357901312)]} 0 0
[junit4:junit4] 2> 1091394 T3296 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1435856854357901312)]} 0 3
[junit4:junit4] 2> 1091397 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1435856854363144192)]} 0 1
[junit4:junit4] 2> 1091403 T3314 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1435856854368387072)]} 0 0
[junit4:junit4] 2> 1091404 T3281 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1435856854368387072)]} 0 3
[junit4:junit4] 2> 1091405 T3298 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22]} 0 6
[junit4:junit4] 2> 1091408 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1435856854374678528)]} 0 1
[junit4:junit4] 2> 1091413 T3328 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1435856854377824256)]} 0 0
[junit4:junit4] 2> 1091414 T3295 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1435856854377824256)]} 0 4
[junit4:junit4] 2> 1091417 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1435856854384115712)]} 0 1
[junit4:junit4] 2> 1091423 T3312 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1435856854389358592)]} 0 0
[junit4:junit4] 2> 1091424 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[24 (1435856854389358592)]} 0 3
[junit4:junit4] 2> 1091425 T3297 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24]} 0 6
[junit4:junit4] 2> 1091427 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1435856854395650048)]} 0 0
[junit4:junit4] 2> 1091435 T3329 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1435856854400892928)]} 0 0
[junit4:junit4] 2> 1091436 T3296 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[25 (1435856854400892928)]} 0 4
[junit4:junit4] 2> 1091436 T3280 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25]} 0 6
[junit4:junit4] 2> 1091440 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1435856854408232960)]} 0 1
[junit4:junit4] 2> 1091447 T3331 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1435856854413475840)]} 0 0
[junit4:junit4] 2> 1091448 T3298 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[26 (1435856854413475840)]} 0 4
[junit4:junit4] 2> 1091449 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26]} 0 7
[junit4:junit4] 2> 1091451 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1435856854420815872)]} 0 0
[junit4:junit4] 2> 1091459 T3311 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1435856854426058752)]} 0 0
[junit4:junit4] 2> 1091460 T3281 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[27 (1435856854426058752)]} 0 4
[junit4:junit4] 2> 1091461 T3295 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27]} 0 7
[junit4:junit4] 2> 1091463 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1435856854433398784)]} 0 0
[junit4:junit4] 2> 1091468 T3313 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1435856854436544512)]} 0 0
[junit4:junit4] 2> 1091469 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1435856854436544512)]} 0 4
[junit4:junit4] 2> 1091471 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1435856854441787392)]} 0 0
[junit4:junit4] 2> 1091476 T3330 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1435856854444933120)]} 0 0
[junit4:junit4] 2> 1091477 T3297 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1435856854444933120)]} 0 3
[junit4:junit4] 2> 1091480 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1435856854451224576)]} 0 0
[junit4:junit4] 2> 1091488 T3328 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1435856854456467456)]} 0 1
[junit4:junit4] 2> 1091489 T3296 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1435856854456467456)]} 0 4
[junit4:junit4] 2> 1091489 T3280 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30]} 0 6
[junit4:junit4] 2> 1091492 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1435856854463807488)]} 0 0
[junit4:junit4] 2> 1091500 T3329 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1435856854469050368)]} 0 1
[junit4:junit4] 2> 1091501 T3298 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[31 (1435856854469050368)]} 0 4
[junit4:junit4] 2> 1091501 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31]} 0 6
[junit4:junit4] 2> 1091504 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1435856854476390400)]} 0 0
[junit4:junit4] 2> 1091510 T3314 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1435856854479536128)]} 0 1
[junit4:junit4] 2> 1091511 T3281 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1435856854479536128)]} 0 4
[junit4:junit4] 2> 1091513 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1435856854485827584)]} 0 0
[junit4:junit4] 2> 1091519 T3331 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1435856854488973312)]} 0 1
[junit4:junit4] 2> 1091520 T3295 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1435856854488973312)]} 0 4
[junit4:junit4] 2> 1091523 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1435856854495264768)]} 0 1
[junit4:junit4] 2> 1091528 T3312 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1435856854499459072)]} 0 1
[junit4:junit4] 2> 1091529 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1435856854499459072)]} 0 4
[junit4:junit4] 2> 1091532 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1435856854505750528)]} 0 0
[junit4:junit4] 2> 1091537 T3311 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1435856854508896256)]} 0 0
[junit4:junit4] 2> 1091538 T3280 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1435856854508896256)]} 0 3
[junit4:junit4] 2> 1091540 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1435856854514139136)]} 0 0
[junit4:junit4] 2> 1091545 T3313 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1435856854517284864)]} 0 0
[junit4:junit4] 2> 1091546 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1435856854517284864)]} 0 3
[junit4:junit4] 2> 1091548 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1435856854522527744)]} 0 0
[junit4:junit4] 2> 1091553 T3330 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1435856854524624896)]} 0 1
[junit4:junit4] 2> 1091553 T3297 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1435856854524624896)]} 0 3
[junit4:junit4] 2> 1091556 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1435856854530916352)]} 0 1
[junit4:junit4] 2> 1091561 T3314 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1435856854534062080)]} 0 0
[junit4:junit4] 2> 1091562 T3281 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1435856854534062080)]} 0 4
[junit4:junit4] 2> 1091564 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1435856854539304960)]} 0 0
[junit4:junit4] 2> 1091572 T3328 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1435856854544547840)]} 0 1
[junit4:junit4] 2> 1091573 T3296 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[39 (1435856854544547840)]} 0 4
[junit4:junit4] 2> 1091573 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39]} 0 6
[junit4:junit4] 2> 1091576 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1435856854551887872)]} 0 0
[junit4:junit4] 2> 1091585 T3311 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1435856854558179328)]} 0 1
[junit4:junit4] 2> 1091586 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[40 (1435856854558179328)]} 0 4
[junit4:junit4] 2> 1091586 T3298 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40]} 0 7
[junit4:junit4] 2> 1091589 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1435856854565519360)]} 0 1
[junit4:junit4] 2> 1091594 T3314 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1435856854567616512)]} 0 0
[junit4:junit4] 2> 1091595 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1435856854567616512)]} 0 4
[junit4:junit4] 2> 1091598 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1435856854573907968)]} 0 1
[junit4:junit4] 2> 1091603 T3312 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1435856854577053696)]} 0 1
[junit4:junit4] 2> 1091605 T3280 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1435856854577053696)]} 0 5
[junit4:junit4] 2> 1091608 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1435856854584393728)]} 0 1
[junit4:junit4] 2> 1091613 T3313 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1435856854587539456)]} 0 1
[junit4:junit4] 2> 1091613 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1435856854587539456)]} 0 3
[junit4:junit4] 2> 1091616 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1435856854593830912)]} 0 0
[junit4:junit4] 2> 1091622 T3311 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1435856854596976640)]} 0 0
[junit4:junit4] 2> 1091623 T3281 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1435856854596976640)]} 0 4
[junit4:junit4] 2> 1091626 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1435856854604316672)]} 0 0
[junit4:junit4] 2> 1091633 T3329 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1435856854609559552)]} 0 1
[junit4:junit4] 2> 1091634 T3297 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[45 (1435856854609559552)]} 0 4
[junit4:junit4] 2> 1091634 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45]} 0 5
[junit4:junit4] 2> 1091637 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1435856854615851008)]} 0 0
[junit4:junit4] 2> 1091644 T3314 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1435856854620045312)]} 0 1
[junit4:junit4] 2> 1091644 T3280 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[46 (1435856854620045312)]} 0 3
[junit4:junit4] 2> 1091645 T3295 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46]} 0 6
[junit4:junit4] 2> 1091648 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1435856854627385344)]} 0 1
[junit4:junit4] 2> 1091656 T3312 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1435856854632628224)]} 0 1
[junit4:junit4] 2> 1091656 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[47 (1435856854632628224)]} 0 3
[junit4:junit4] 2> 1091657 T3298 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47]} 0 6
[junit4:junit4] 2> 1091660 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1435856854638919680)]} 0 1
[junit4:junit4] 2> 1091666 T3313 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1435856854643113984)]} 0 1
[junit4:junit4] 2> 1091667 T3281 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1435856854643113984)]} 0 4
[junit4:junit4] 2> 1091670 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1435856854650454016)]} 0 1
[junit4:junit4] 2> 1091678 T3311 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1435856854655696896)]} 0 1
[junit4:junit4] 2> 1091679 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[49 (1435856854655696896)]} 0 4
[junit4:junit4] 2> 1091679 T3296 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49]} 0 6
[junit4:junit4] 2> 1091682 T3260 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1435856854663036928)]} 0 0
[junit4:junit4] 2> 1091691 T3314 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1435856854669328384)]} 0 1
[junit4:junit4] 2> 1091691 T3280 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[50 (1435856854669328384)]} 0 4
[junit4:junit4] 2> 1091692 T3297 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50]} 0 7
[junit4:junit4] 2> 1091695 T3259 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1435856854675619840)]} 0 1
[junit4:junit4] 2> 1091700 T3312 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1435856854678765568)]} 0 1
[junit4:junit4] 2> 1091701 T3282 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1435856854678765568)]} 0 4
[junit4:junit4] 2> 1091703 T3261 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1435856854685057024)]} 0 0
[junit4:junit4] 2> 1091711 T3313 C2763 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1435856854690299904)]} 0 1
[junit4:junit4] 2> 1091712 T3281 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[52 (1435856854690299904)]} 0 4
[junit4:junit4] 2> 1091712 T3295 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52]} 0 6
[junit4:junit4] 2> 1091715 T3262 C2766 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1435856854697639936)]} 0 0
[junit4:junit4] 2> 1091722 T3330 C2762 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1435856854701834240)]} 0 1
[junit4:junit4] 2> 1091723 T3298 C2765 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1435856854701834240)]} 0 4
[junit4:junit4] 2> 1091723 T3279 C2764 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53]} 0 6
[junit4:junit4] 2> ASYNC NEW_CORE C2767 name=collection1 org.apache.solr.core.SolrCore@5d3b9017 url=http://127.0.0.1:44638/collection1 node=127.0.0.1:44638_ C2767_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:44638_, base_url=http://127.0.0.1:44638, leader=true}
[junit4:junit4] 2> 1091733 T3260 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1435856854716514304)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C2768 name=collection1 org.apache.solr.core.SolrCore@b964b1a url=http://127.0.0.1:40946/collection1 node=127.0.0.1:40946_ C2768_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:40946_, base_url=http://127.0.0.1:40946}
[junit4:junit4] 2> 1091739 T3311 C2768 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1435856854720708608)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C2769 name=collection1 org.apache.solr.core.SolrCore@7d77b5ec url=http://127.0.0.1:52097/collection1 node=127.0.0.1:52097_ C2769_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52097_, base_url=http://127.0.0.1:52097, leader=true}
[junit4:junit4] 2> 1091740 T3280 C2769 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1435856854720708608)]} 0 4
[junit4:junit4] 2> 1091743 T3259 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1435856854727000064)]} 0 1
[junit4:junit4] 2> 1091749 T3314 C2768 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1435856854731194368)]} 0 0
[junit4:junit4] 2> 1091750 T3282 C2769 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[55 (1435856854731194368)]} 0 3
[junit4:junit4] 2> ASYNC NEW_CORE C2770 name=collection1 org.apache.solr.core.SolrCore@752788d3 url=http://127.0.0.1:43386/collection1 node=127.0.0.1:43386_ C2770_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43386_, base_url=http://127.0.0.1:43386, leader=true}
[junit4:junit4] 2> 1091751 T3296 C2770 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55]} 0 6
[junit4:junit4] 2> 1091754 T3261 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1435856854737485824)]} 0 1
[junit4:junit4] 2> ASYNC NEW_CORE C2771 name=collection1 org.apache.solr.core.SolrCore@4f3b8158 url=http://127.0.0.1:43402/collection1 node=127.0.0.1:43402_ C2771_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43402_, base_url=http://127.0.0.1:43402}
[junit4:junit4] 2> 1091760 T3328 C2771 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1435856854742728704)]} 0 0
[junit4:junit4] 2> 1091761 T3297 C2770 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[56 (1435856854742728704)]} 0 3
[junit4:junit4] 2> 1091762 T3281 C2769 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56]} 0 6
[junit4:junit4] 2> 1091765 T3262 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1435856854749020160)]} 0 1
[junit4:junit4] 2> 1091769 T3331 C2771 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1435856854752165888)]} 0 0
[junit4:junit4] 2> 1091770 T3295 C2770 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1435856854752165888)]} 0 3
[junit4:junit4] 2> 1091773 T3260 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1435856854758457344)]} 0 1
[junit4:junit4] 2> 1091778 T3329 C2771 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1435856854760554496)]} 0 0
[junit4:junit4] 2> 1091779 T3298 C2770 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1435856854760554496)]} 0 4
[junit4:junit4] 2> 1091782 T3259 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1435856854766845952)]} 0 1
[junit4:junit4] 2> 1091787 T3312 C2768 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1435856854769991680)]} 0 1
[junit4:junit4] 2> 1091787 T3279 C2769 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1435856854769991680)]} 0 3
[junit4:junit4] 2> 1091790 T3261 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1435856854776283136)]} 0 0
[junit4:junit4] 2> 1091795 T3330 C2771 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1435856854779428864)]} 0 0
[junit4:junit4] 2> 1091796 T3296 C2770 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1435856854779428864)]} 0 4
[junit4:junit4] 2> 1091799 T3262 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1435856854784671744)]} 0 1
[junit4:junit4] 2> 1091806 T3313 C2768 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1435856854790963200)]} 0 0
[junit4:junit4] 2> 1091807 T3280 C2769 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[61 (1435856854790963200)]} 0 4
[junit4:junit4] 2> 1091808 T3297 C2770 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61]} 0 7
[junit4:junit4] 2> 1091810 T3260 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1435856854797254656)]} 0 0
[junit4:junit4] 2> 1091815 T3328 C2771 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1435856854800400384)]} 0 0
[junit4:junit4] 2> 1091816 T3295 C2770 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1435856854800400384)]} 0 3
[junit4:junit4] 2> 1091819 T3259 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1435856854806691840)]} 0 0
[junit4:junit4] 2> 1091824 T3311 C2768 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1435856854809837568)]} 0 0
[junit4:junit4] 2> 1091825 T3282 C2769 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1435856854809837568)]} 0 3
[junit4:junit4] 2> 1091828 T3261 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1435856854815080448)]} 0 1
[junit4:junit4] 2> 1091835 T3314 C2768 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1435856854820323328)]} 0 1
[junit4:junit4] 2> 1091835 T3281 C2769 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[64 (1435856854820323328)]} 0 3
[junit4:junit4] 2> 1091836 T3298 C2770 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64]} 0 6
[junit4:junit4] 2> 1091838 T3262 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1435856854826614784)]} 0 0
[junit4:junit4] 2> 1091844 T3312 C2768 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1435856854829760512)]} 0 0
[junit4:junit4] 2> 1091845 T3279 C2769 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1435856854829760512)]} 0 4
[junit4:junit4] 2> 1091848 T3260 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1435856854837100544)]} 0 1
[junit4:junit4] 2> 1091854 T3313 C2768 P40946 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1435856854841294848)]} 0 0
[junit4:junit4] 2> 1091855 T3280 C2769 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[66 (1435856854841294848)]} 0 3
[junit4:junit4] 2> 1091856 T3296 C2770 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66]} 0 6
[junit4:junit4] 2> 1091858 T3259 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1435856854847586304)]} 0 0
[junit4:junit4] 2> 1091864 T3331 C2771 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1435856854851780608)]} 0 0
[junit4:junit4] 2> 1091865 T3297 C2770 P43386 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52097/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[67 (1435856854851780608)]} 0 3
[junit4:junit4] 2> 1091865 T3282 C2769 P52097 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67]} 0 5
[junit4:junit4] 2> 1091868 T3261 C2767 P44638 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1435856854858072064)]} 0 1
[junit4:junit4] 2> 1091874 T3329 C2771 P43402 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:43386/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[68 (1435856854862266368)]} 0 0
[junit4:junit4] 2> 1091875 T3295 C2770 P43386 oasup.LogUpdateProcessor.finish [collection1] weba
[...truncated too long message...]
jsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 1263398 T3244 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1263400 T3244 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:58632 58632
[junit4:junit4] 2> 1263502 T3412 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@297092b0 name:ZooKeeperConnection Watcher:127.0.0.1:58632/solr got event WatchedEvent state:Disconnected type:None path:null path:null type:None
[junit4:junit4] 2> 1263502 T3412 oascc.ConnectionManager.process Client->ZooKeeper status change trigger but we are already closed
[junit4:junit4] 2> 1263505 T3244 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 44638
[junit4:junit4] 2> !!!! WARNING: best effort to remove /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369339778233 FAILED !!!!!
[junit4:junit4] 2> 1263506 T3244 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1263506 T3244 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:58632 58632
[junit4:junit4] 1> "core":"collection1_shard1_0_replica1",
[junit4:junit4] 1> "node_name":"127.0.0.1:40946_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40946"}
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1_1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1_shard1_1_replica1",
[junit4:junit4] 1> "node_name":"127.0.0.1:40946_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40946"}
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard2 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:43386_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:43386"}
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/shards (0)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/89741051706474499-127.0.0.1:44638__collection1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4:junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:44638_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:44638"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (6)
[junit4:junit4] 1> /solr/overseer_elect/election/89741051706474512-127.0.0.1:58632_solr-n_0000000007 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89741051706474508-127.0.0.1:43402_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89741051706474504-127.0.0.1:43386_-n_0000000002 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89741051706474499-127.0.0.1:44638_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89741051706474510-127.0.0.1:52097_-n_0000000005 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89741051706474506-127.0.0.1:40946_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89741051706474499-127.0.0.1:44638_-n_0000000000"}
[junit4:junit4] 1> /zookeeper (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeyShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=92DF274D78CC583E -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=en_US -Dtests.timezone=Pacific/Honolulu -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 198s J1 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: Wrong doc count on shard1_0 expected:<393> but was:<392>
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([92DF274D78CC583E:1339A9550F933802]:0)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(ShardSplitTest.java:166)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:155)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 1263525 T3244 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 197946 T3243 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 1264618 T3335 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1264619 T3335 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> 1264619 T3335 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=en_US, timezone=Pacific/Honolulu
[junit4:junit4] 2> NOTE: Linux 3.2.0-41-generic amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=8,threads=2,free=165733000,total=518979584
[junit4:junit4] 2> NOTE: All tests run in this JVM: [FieldAnalysisRequestHandlerTest, TestUniqueKeyFieldResource, ZkSolrClientTest, BasicDistributedZk2Test, NotRequiredUniqueKeyTest, TestNumberUtils, TestComponentsName, TestElisionMultitermQuery, SpellCheckComponentTest, ZkNodePropsTest, TestLMJelinekMercerSimilarityFactory, TestFieldTypeResource, TestCSVLoader, SampleTest, TestCodecSupport, TestWordDelimiterFilterFactory, SignatureUpdateProcessorFactoryTest, DirectUpdateHandlerTest, ConvertedLegacyTest, SortByFunctionTest, PathHierarchyTokenizerFactoryTest, TestDistributedGrouping, TestIndexSearcher, TestCoreDiscovery, TestDefaultSimilarityFactory, TestOmitPositions, IndexReaderFactoryTest, HighlighterConfigTest, XsltUpdateRequestHandlerTest, TestDFRSimilarityFactory, FileUtilsTest, LeaderElectionIntegrationTest, OutputWriterTest, StandardRequestHandlerTest, BasicZkTest, TestJmxIntegration, TestReload, TestMaxScoreQueryParser, TestSolrQueryParserDefaultOperatorResource, UniqFieldsUpdateProcessorFactoryTest, IndexSchemaRuntimeFieldTest, TestBM25SimilarityFactory, TestUtils, TestPostingsSolrHighlighter, CoreContainerCoreInitFailuresTest, SolrRequestParserTest, TestSolr4Spatial, TestFastOutputStream, TestSuggestSpellingConverter, TestFiltering, SimplePostToolTest, TermVectorComponentDistributedTest, SpellCheckCollatorTest, TestRangeQuery, TestAtomicUpdateErrorCases, TestSolrXMLSerializer, DisMaxRequestHandlerTest, IndexBasedSpellCheckerTest, SuggesterTSTTest, CurrencyFieldOpenExchangeTest, TestPartialUpdateDeduplication, XmlUpdateRequestHandlerTest, TestShardHandlerFactory, SolrCoreCheckLockOnStartupTest, TestDistributedSearch, DistanceFunctionTest, BadIndexSchemaTest, SuggesterWFSTTest, MultiTermTest, BasicDistributedZkTest, ChaosMonkeySafeLeaderTest, CollectionsAPIDistributedZkTest, ShardRoutingTest, FullSolrCloudDistribCmdsTest, ClusterStateUpdateTest, TestRandomFaceting, SliceStateUpdateTest, TestRecovery, TestHashPartitioner, TestMultiCoreConfBootstrap, HardAutoCommitTest, DistributedTermsComponentTest, SolrCoreTest, StatsComponentTest, TestGroupingSearch, SoftAutoCommitTest, SuggesterTest, TestTrie, NoCacheHeaderTest, TestUpdate, TestRemoteStreaming, DebugComponentTest, LukeRequestHandlerTest, DocumentAnalysisRequestHandlerTest, FileBasedSpellCheckerTest, RequestHandlersTest, TestValueSourceCache, RequiredFieldsTest, TestArbitraryIndexDir, TestCollationField, JSONWriterTest, QueryParsingTest, TestPHPSerializedResponseWriter, TestBinaryResponseWriter, UpdateParamsTest, CopyFieldTest, TestStressRecovery, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 199.23s, 1 test, 1 failure <<< FAILURES!
[...truncated 10 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:366: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:887: There were test failures: 296 suites, 1234 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 39 minutes 1 second
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_21 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
Re: [JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.8.0-ea-b89) - Build #
5736 - Still Failing!
Posted by Martijn v Groningen <ma...@gmail.com>.
Committed a fix for this. Hopefully it doesn't fail any more.
On 23 May 2013 23:14, Policeman Jenkins Server <je...@thetaphi.de> wrote:
> Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5736/
> Java: 64bit/jdk1.8.0-ea-b89 -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC
>
> 1 tests failed.
> REGRESSION:
> org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest.testBasic
>
> Error Message:
> testBasic(org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest):
> Insane FieldCache usage(s) found expected:<0> but was:<2>
>
> Stack Trace:
> java.lang.AssertionError:
> testBasic(org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest):
> Insane FieldCache usage(s) found expected:<0> but was:<2>
> at
> __randomizedtesting.SeedInfo.seed([DDCF295067251A85:76353445B8F99CAB]:0)
> at org.junit.Assert.fail(Assert.java:93)
> at org.junit.Assert.failNotEquals(Assert.java:647)
> at org.junit.Assert.assertEquals(Assert.java:128)
> at org.junit.Assert.assertEquals(Assert.java:472)
> at
> org.apache.lucene.util.LuceneTestCase.assertSaneFieldCaches(LuceneTestCase.java:614)
> at
> org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:55)
> 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
> 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 7110 lines...]
> [junit4:junit4] Suite:
> org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest
> [junit4:junit4] 2> *** BEGIN
> testBasic(org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest):
> Insane FieldCache usage(s) ***
> [junit4:junit4] 2> VALUEMISMATCH: Multiple distinct value objects for
> java.lang.Object@6facf655+id
> [junit4:junit4] 2> 'java.lang.Object@6facf655'=>'id',int,org.apache.lucene.search.FieldCache.DEFAULT_INT_PARSER=>org.apache.lucene.search.FieldCacheImpl$IntsFromArray#1584282652
> (size =~ 48 bytes)
> [junit4:junit4] 2> 'java.lang.Object@6facf655'=>'id',int,null=>org.apache.lucene.search.FieldCacheImpl$IntsFromArray#1584282652
> (size =~ 48 bytes)
> [junit4:junit4] 2> 'java.lang.Object@6facf655'=>'id',class
> org.apache.lucene.index.SortedDocValues,0.5=>org.apache.lucene.search.FieldCacheImpl$SortedDocValuesImpl#1849007812
> (size =~ 232 bytes)
> [junit4:junit4] 2>
> [junit4:junit4] 2> VALUEMISMATCH: Multiple distinct value objects for
> java.lang.Object@18b483cf+id
> [junit4:junit4] 2> 'java.lang.Object@18b483cf'=>'id',class
> org.apache.lucene.index.SortedDocValues,0.5=>org.apache.lucene.search.FieldCacheImpl$SortedDocValuesImpl#1220004390
> (size =~ 232 bytes)
> [junit4:junit4] 2> 'java.lang.Object@18b483cf'=>'id',int,org.apache.lucene.search.FieldCache.DEFAULT_INT_PARSER=>org.apache.lucene.search.FieldCacheImpl$IntsFromArray#834824503
> (size =~ 56 bytes)
> [junit4:junit4] 2> 'java.lang.Object@18b483cf'=>'id',int,null=>org.apache.lucene.search.FieldCacheImpl$IntsFromArray#834824503
> (size =~ 56 bytes)
> [junit4:junit4] 2>
> [junit4:junit4] 2> *** END
> testBasic(org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest):
> Insane FieldCache usage(s) ***
> [junit4:junit4] 2> NOTE: reproduce with: ant test
> -Dtestcase=AllGroupHeadsCollectorTest -Dtests.method=testBasic
> -Dtests.seed=DDCF295067251A85 -Dtests.multiplier=3 -Dtests.slow=true
> -Dtests.locale=es_NI -Dtests.timezone=Antarctica/Casey
> -Dtests.file.encoding=US-ASCII
> [junit4:junit4] FAILURE 0.93s J1 | AllGroupHeadsCollectorTest.testBasic <<<
> [junit4:junit4] > Throwable #1: java.lang.AssertionError:
> testBasic(org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest):
> Insane FieldCache usage(s) found expected:<0> but was:<2>
> [junit4:junit4] > at
> __randomizedtesting.SeedInfo.seed([DDCF295067251A85:76353445B8F99CAB]:0)
> [junit4:junit4] > at
> org.apache.lucene.util.LuceneTestCase.assertSaneFieldCaches(LuceneTestCase.java:614)
> [junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
> [junit4:junit4] 2> NOTE: test params are: codec=Lucene42:
> {sort1=Lucene41(blocksize=128), sort2=PostingsFormat(name=Memory doPackFST=
> false), author=PostingsFormat(name=MockSep), group=Lucene41(blocksize=128),
> content=PostingsFormat(name=MockSep), sort3=PostingsFormat(name=MockSep),
> id=Lucene41(blocksize=128)},
> docValues:{author_dv=DocValuesFormat(name=CheapBastard),
> group_dv=DocValuesFormat(name=CheapBastard)}, sim=DefaultSimilarity,
> locale=es_NI, timezone=Antarctica/Casey
> [junit4:junit4] 2> NOTE: Linux 3.2.0-41-generic amd64/Oracle Corporation
> 1.8.0-ea (64-bit)/cpus=8,threads=1,free=78030624,total=126418944
> [junit4:junit4] 2> NOTE: All tests run in this JVM:
> [AllGroupHeadsCollectorTest]
> [junit4:junit4] Completed on J1 in 7.97s, 2 tests, 1 failure <<< FAILURES!
>
> [...truncated 22 lines...]
> BUILD FAILED
> /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:386: The
> following error occurred while executing this line:
> /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:366: The
> following error occurred while executing this line:
> /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The
> following error occurred while executing this line:
> /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/build.xml:554: The
> following error occurred while executing this line:
> /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1827:
> The following error occurred while executing this line:
> /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/module-build.xml:61:
> The following error occurred while executing this line:
> /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1243:
> The following error occurred while executing this line:
> /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:887:
> There were test failures: 6 suites, 12 tests, 1 failure
>
> Total time: 17 minutes 26 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
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> For additional commands, e-mail: dev-help@lucene.apache.org
>
--
Met vriendelijke groet,
Martijn van Groningen
[JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.8.0-ea-b89) - Build #
5736 - Still Failing!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5736/
Java: 64bit/jdk1.8.0-ea-b89 -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest.testBasic
Error Message:
testBasic(org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest): Insane FieldCache usage(s) found expected:<0> but was:<2>
Stack Trace:
java.lang.AssertionError: testBasic(org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest): Insane FieldCache usage(s) found expected:<0> but was:<2>
at __randomizedtesting.SeedInfo.seed([DDCF295067251A85:76353445B8F99CAB]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.apache.lucene.util.LuceneTestCase.assertSaneFieldCaches(LuceneTestCase.java:614)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:55)
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 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 7110 lines...]
[junit4:junit4] Suite: org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest
[junit4:junit4] 2> *** BEGIN testBasic(org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest): Insane FieldCache usage(s) ***
[junit4:junit4] 2> VALUEMISMATCH: Multiple distinct value objects for java.lang.Object@6facf655+id
[junit4:junit4] 2> 'java.lang.Object@6facf655'=>'id',int,org.apache.lucene.search.FieldCache.DEFAULT_INT_PARSER=>org.apache.lucene.search.FieldCacheImpl$IntsFromArray#1584282652 (size =~ 48 bytes)
[junit4:junit4] 2> 'java.lang.Object@6facf655'=>'id',int,null=>org.apache.lucene.search.FieldCacheImpl$IntsFromArray#1584282652 (size =~ 48 bytes)
[junit4:junit4] 2> 'java.lang.Object@6facf655'=>'id',class org.apache.lucene.index.SortedDocValues,0.5=>org.apache.lucene.search.FieldCacheImpl$SortedDocValuesImpl#1849007812 (size =~ 232 bytes)
[junit4:junit4] 2>
[junit4:junit4] 2> VALUEMISMATCH: Multiple distinct value objects for java.lang.Object@18b483cf+id
[junit4:junit4] 2> 'java.lang.Object@18b483cf'=>'id',class org.apache.lucene.index.SortedDocValues,0.5=>org.apache.lucene.search.FieldCacheImpl$SortedDocValuesImpl#1220004390 (size =~ 232 bytes)
[junit4:junit4] 2> 'java.lang.Object@18b483cf'=>'id',int,org.apache.lucene.search.FieldCache.DEFAULT_INT_PARSER=>org.apache.lucene.search.FieldCacheImpl$IntsFromArray#834824503 (size =~ 56 bytes)
[junit4:junit4] 2> 'java.lang.Object@18b483cf'=>'id',int,null=>org.apache.lucene.search.FieldCacheImpl$IntsFromArray#834824503 (size =~ 56 bytes)
[junit4:junit4] 2>
[junit4:junit4] 2> *** END testBasic(org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest): Insane FieldCache usage(s) ***
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=AllGroupHeadsCollectorTest -Dtests.method=testBasic -Dtests.seed=DDCF295067251A85 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_NI -Dtests.timezone=Antarctica/Casey -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 0.93s J1 | AllGroupHeadsCollectorTest.testBasic <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: testBasic(org.apache.lucene.search.grouping.AllGroupHeadsCollectorTest): Insane FieldCache usage(s) found expected:<0> but was:<2>
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([DDCF295067251A85:76353445B8F99CAB]:0)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.assertSaneFieldCaches(LuceneTestCase.java:614)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {sort1=Lucene41(blocksize=128), sort2=PostingsFormat(name=Memory doPackFST= false), author=PostingsFormat(name=MockSep), group=Lucene41(blocksize=128), content=PostingsFormat(name=MockSep), sort3=PostingsFormat(name=MockSep), id=Lucene41(blocksize=128)}, docValues:{author_dv=DocValuesFormat(name=CheapBastard), group_dv=DocValuesFormat(name=CheapBastard)}, sim=DefaultSimilarity, locale=es_NI, timezone=Antarctica/Casey
[junit4:junit4] 2> NOTE: Linux 3.2.0-41-generic amd64/Oracle Corporation 1.8.0-ea (64-bit)/cpus=8,threads=1,free=78030624,total=126418944
[junit4:junit4] 2> NOTE: All tests run in this JVM: [AllGroupHeadsCollectorTest]
[junit4:junit4] Completed on J1 in 7.97s, 2 tests, 1 failure <<< FAILURES!
[...truncated 22 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:366: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/build.xml:554: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1827: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/module-build.xml:61: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:887: There were test failures: 6 suites, 12 tests, 1 failure
Total time: 17 minutes 26 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