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/06/01 20:49:03 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.6.0_45) - Build # 5872
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5872/
Java: 32bit/jdk1.6.0_45 -client -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:36381 returned non ok status:500, message:Server Error
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:36381 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([E473EFEF7429C718:659561F70376A724]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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:662)
Build Log:
[...truncated 8797 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 138450 T521 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 138454 T521 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeyShardSplitTest-1370111238896
[junit4:junit4] 2> 138455 T521 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 138455 T522 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 138555 T521 oasc.ZkTestServer.run start zk server on port:41168
[junit4:junit4] 2> 138557 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 138617 T528 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1327667 name:ZooKeeperConnection Watcher:127.0.0.1:41168 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 138617 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 138618 T521 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 138625 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 138626 T530 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ff5d6c name:ZooKeeperConnection Watcher:127.0.0.1:41168/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 138627 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 138628 T521 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 138632 T521 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 138636 T521 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 138638 T521 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 138642 T521 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> 138643 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 138649 T521 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> 138650 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 138654 T521 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> 138655 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 138659 T521 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> 138660 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 138664 T521 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> 138665 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 138669 T521 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> 138670 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 138674 T521 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> 138675 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 138678 T521 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> 138679 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 138683 T521 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> 138684 T521 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 138780 T521 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 138784 T521 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50022
[junit4:junit4] 2> 138784 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 138784 T521 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 138785 T521 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370111239132
[junit4:junit4] 2> 138785 T521 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370111239132/solr.xml
[junit4:junit4] 2> 138786 T521 oasc.CoreContainer.<init> New CoreContainer 27152267
[junit4:junit4] 2> 138786 T521 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370111239132/'
[junit4:junit4] 2> 138786 T521 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370111239132/'
[junit4:junit4] 2> 138840 T521 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 138840 T521 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 138840 T521 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 138841 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 138841 T521 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 138842 T521 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 138842 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 138842 T521 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 138843 T521 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 138843 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 138846 T521 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 138846 T521 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:41168/solr
[junit4:junit4] 2> 138847 T521 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 138848 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 138849 T541 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@38df00 name:ZooKeeperConnection Watcher:127.0.0.1:41168 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 138849 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 138851 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 138854 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 138856 T543 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@fd28f8 name:ZooKeeperConnection Watcher:127.0.0.1:41168/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 138856 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 138858 T521 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 138861 T521 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 138863 T521 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 138864 T521 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50022_
[junit4:junit4] 2> 138865 T521 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50022_
[junit4:junit4] 2> 138868 T521 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 138873 T521 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 138876 T521 oasc.Overseer.start Overseer (id=89791610152484867-127.0.0.1:50022_-n_0000000000) starting
[junit4:junit4] 2> 138880 T521 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 138885 T545 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 138886 T521 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 138889 T521 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 138892 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 138897 T544 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 138902 T546 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370111239132/collection1
[junit4:junit4] 2> 138903 T546 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 138904 T546 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 138904 T546 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 138906 T546 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370111239132/collection1/'
[junit4:junit4] 2> 138907 T546 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370111239132/collection1/lib/README' to classloader
[junit4:junit4] 2> 138908 T546 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370111239132/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 138931 T3 oasc.CoreContainer.finalize ERROR CoreContainer was not shutdown prior to finalize(), indicates a bug -- POSSIBLE RESOURCE LEAK!!! instance=10836077
[junit4:junit4] 2> 138955 T546 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 138996 T546 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 138998 T546 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 139002 T546 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 139383 T546 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 139386 T546 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 139387 T546 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 139391 T546 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 139414 T546 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 139414 T546 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370111239132/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/control/data/
[junit4:junit4] 2> 139414 T546 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@b1cd0
[junit4:junit4] 2> 139415 T546 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 139416 T546 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/control/data
[junit4:junit4] 2> 139416 T546 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/control/data/index/
[junit4:junit4] 2> 139416 T546 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 139418 T546 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/control/data/index
[junit4:junit4] 2> 139420 T546 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1d4bee1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e643a7),segFN=segments_1,generation=1}
[junit4:junit4] 2> 139421 T546 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 139423 T546 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 139424 T546 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 139425 T546 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 139426 T546 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 139427 T546 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 139427 T546 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 139427 T546 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 139428 T546 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 139428 T546 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 139430 T546 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 139432 T546 oass.SolrIndexSearcher.<init> Opening Searcher@1e84f99 main
[junit4:junit4] 2> 139433 T546 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/control/data/tlog
[junit4:junit4] 2> 139433 T546 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 139434 T546 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 139436 T547 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1e84f99 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 139438 T546 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 139438 T546 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 140402 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 140403 T544 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:50022_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50022"}
[junit4:junit4] 2> 140404 T544 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 140404 T544 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 140409 T543 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> 140440 T546 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 140440 T546 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50022 collection:control_collection shard:shard1
[junit4:junit4] 2> 140442 T546 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 140451 T546 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 140454 T546 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 140455 T546 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 140455 T546 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50022/collection1/
[junit4:junit4] 2> 140456 T546 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 140456 T546 oasc.SyncStrategy.syncToMe http://127.0.0.1:50022/collection1/ has no replicas
[junit4:junit4] 2> 140457 T546 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50022/collection1/
[junit4:junit4] 2> 140457 T546 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 141915 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 141926 T543 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> 141969 T546 oasc.ZkController.register We are http://127.0.0.1:50022/collection1/ and leader is http://127.0.0.1:50022/collection1/
[junit4:junit4] 2> 141969 T546 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50022
[junit4:junit4] 2> 141970 T546 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 141970 T546 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 141970 T546 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 141972 T546 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 141974 T521 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 141975 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 141976 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 141982 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 141985 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 141986 T550 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bdd156 name:ZooKeeperConnection Watcher:127.0.0.1:41168/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 141987 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 141989 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 141993 T521 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 142073 T521 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 142075 T521 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:36381
[junit4:junit4] 2> 142075 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 142076 T521 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 142076 T521 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370111242435
[junit4:junit4] 2> 142076 T521 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370111242435/solr.xml
[junit4:junit4] 2> 142077 T521 oasc.CoreContainer.<init> New CoreContainer 452849
[junit4:junit4] 2> 142077 T521 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370111242435/'
[junit4:junit4] 2> 142077 T521 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370111242435/'
[junit4:junit4] 2> 142128 T521 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 142128 T521 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 142129 T521 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 142129 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 142129 T521 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 142130 T521 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 142130 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 142130 T521 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 142131 T521 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 142131 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 142134 T521 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 142134 T521 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:41168/solr
[junit4:junit4] 2> 142135 T521 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 142136 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 142137 T561 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@aabe71 name:ZooKeeperConnection Watcher:127.0.0.1:41168 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 142138 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 142139 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 142143 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 142145 T563 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a355b7 name:ZooKeeperConnection Watcher:127.0.0.1:41168/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 142145 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 142149 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 143151 T521 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36381_
[junit4:junit4] 2> 143153 T521 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36381_
[junit4:junit4] 2> 143155 T543 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> 143155 T550 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 143155 T563 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 143156 T543 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 143162 T564 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370111242435/collection1
[junit4:junit4] 2> 143162 T564 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 143166 T564 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 143166 T564 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 143169 T564 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370111242435/collection1/'
[junit4:junit4] 2> 143170 T564 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370111242435/collection1/lib/README' to classloader
[junit4:junit4] 2> 143170 T564 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370111242435/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 143216 T564 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 143275 T564 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 143277 T564 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 143284 T564 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 143433 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 143433 T544 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50022__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:50022_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50022"}
[junit4:junit4] 2> 143436 T543 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> 143437 T563 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> 143436 T550 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> 143887 T564 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 143892 T564 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 143895 T564 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 143900 T564 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 143935 T564 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 143936 T564 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370111242435/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty1/
[junit4:junit4] 2> 143936 T564 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@b1cd0
[junit4:junit4] 2> 143937 T564 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 143937 T564 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty1
[junit4:junit4] 2> 143938 T564 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty1/index/
[junit4:junit4] 2> 143938 T564 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 143939 T564 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty1/index
[junit4:junit4] 2> 143941 T564 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@cb88c8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fa8450),segFN=segments_1,generation=1}
[junit4:junit4] 2> 143941 T564 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 143943 T564 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 143944 T564 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 143945 T564 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 143946 T564 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 143946 T564 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 143947 T564 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 143947 T564 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 143948 T564 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 143949 T564 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 143951 T564 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 143954 T564 oass.SolrIndexSearcher.<init> Opening Searcher@c9ea1c main
[junit4:junit4] 2> 143954 T564 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty1/tlog
[junit4:junit4] 2> 143955 T564 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 143956 T564 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 143964 T565 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c9ea1c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 143970 T564 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 143971 T564 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 144942 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 144943 T544 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:36381_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36381"}
[junit4:junit4] 2> 144944 T544 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 144944 T544 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 144950 T563 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> 144950 T543 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> 144950 T550 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> 144973 T564 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 144973 T564 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36381 collection:collection1 shard:shard1
[junit4:junit4] 2> 144974 T564 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 144983 T564 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 144989 T564 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 144990 T564 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 144990 T564 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:36381/collection1/
[junit4:junit4] 2> 144991 T564 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 144991 T564 oasc.SyncStrategy.syncToMe http://127.0.0.1:36381/collection1/ has no replicas
[junit4:junit4] 2> 144991 T564 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:36381/collection1/
[junit4:junit4] 2> 144992 T564 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 146456 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 146465 T550 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> 146465 T543 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> 146465 T563 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> 146503 T564 oasc.ZkController.register We are http://127.0.0.1:36381/collection1/ and leader is http://127.0.0.1:36381/collection1/
[junit4:junit4] 2> 146503 T564 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36381
[junit4:junit4] 2> 146504 T564 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 146504 T564 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 146505 T564 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 146507 T564 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 146509 T521 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 146509 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 146510 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 146602 T521 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 146604 T521 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49057
[junit4:junit4] 2> 146605 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 146605 T521 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 146606 T521 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370111246958
[junit4:junit4] 2> 146606 T521 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370111246958/solr.xml
[junit4:junit4] 2> 146606 T521 oasc.CoreContainer.<init> New CoreContainer 15374592
[junit4:junit4] 2> 146607 T521 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370111246958/'
[junit4:junit4] 2> 146608 T521 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370111246958/'
[junit4:junit4] 2> 146679 T521 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 146680 T521 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 146680 T521 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 146680 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 146681 T521 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 146681 T521 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 146681 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 146682 T521 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 146682 T521 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 146683 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 146686 T521 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 146686 T521 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:41168/solr
[junit4:junit4] 2> 146687 T521 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 146688 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 146689 T577 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10e68bc name:ZooKeeperConnection Watcher:127.0.0.1:41168 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 146690 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 146691 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 146694 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 146695 T579 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12d5cf3 name:ZooKeeperConnection Watcher:127.0.0.1:41168/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 146695 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 146697 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 147700 T521 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49057_
[junit4:junit4] 2> 147701 T521 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49057_
[junit4:junit4] 2> 147703 T543 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> 147703 T550 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> 147704 T579 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 147704 T563 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 147704 T563 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> 147705 T543 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 147705 T550 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 147709 T580 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370111246958/collection1
[junit4:junit4] 2> 147709 T580 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 147710 T580 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 147710 T580 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 147711 T580 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370111246958/collection1/'
[junit4:junit4] 2> 147711 T580 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370111246958/collection1/lib/README' to classloader
[junit4:junit4] 2> 147711 T580 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370111246958/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 147757 T580 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 147813 T580 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 147820 T580 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 147830 T580 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 147972 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 147973 T544 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:36381__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:36381_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36381"}
[junit4:junit4] 2> 147978 T550 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> 147978 T579 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> 147978 T543 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> 147978 T563 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> 148416 T580 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 148420 T580 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 148423 T580 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 148430 T580 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 148466 T580 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 148467 T580 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370111246958/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty2/
[junit4:junit4] 2> 148467 T580 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@b1cd0
[junit4:junit4] 2> 148468 T580 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 148469 T580 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty2
[junit4:junit4] 2> 148469 T580 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty2/index/
[junit4:junit4] 2> 148469 T580 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 148470 T580 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty2/index
[junit4:junit4] 2> 148472 T580 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@213dbd lockFactory=org.apache.lucene.store.NativeFSLockFactory@88a142),segFN=segments_1,generation=1}
[junit4:junit4] 2> 148473 T580 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 148476 T580 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 148476 T580 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 148477 T580 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 148478 T580 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 148479 T580 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 148480 T580 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 148480 T580 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 148481 T580 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 148482 T580 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 148485 T580 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 148490 T580 oass.SolrIndexSearcher.<init> Opening Searcher@1dad50f main
[junit4:junit4] 2> 148491 T580 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty2/tlog
[junit4:junit4] 2> 148492 T580 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 148492 T580 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 148500 T581 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1dad50f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 148502 T580 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 148502 T580 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 149505 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 149506 T544 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:49057_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49057"}
[junit4:junit4] 2> 149507 T544 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 149507 T544 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 149514 T550 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> 149514 T579 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> 149514 T563 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> 149514 T543 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> 150504 T580 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 150505 T580 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49057 collection:collection1 shard:shard2
[junit4:junit4] 2> 150506 T580 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 150517 T580 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 150520 T580 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 150521 T580 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 150521 T580 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49057/collection1/
[junit4:junit4] 2> 150522 T580 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 150522 T580 oasc.SyncStrategy.syncToMe http://127.0.0.1:49057/collection1/ has no replicas
[junit4:junit4] 2> 150523 T580 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49057/collection1/
[junit4:junit4] 2> 150523 T580 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 151020 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 151030 T543 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> 151030 T579 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> 151030 T563 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> 151030 T550 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> 151082 T580 oasc.ZkController.register We are http://127.0.0.1:49057/collection1/ and leader is http://127.0.0.1:49057/collection1/
[junit4:junit4] 2> 151082 T580 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49057
[junit4:junit4] 2> 151083 T580 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 151083 T580 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 151084 T580 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 151085 T580 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 151087 T521 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 151088 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 151089 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 151167 T521 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 151169 T521 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39997
[junit4:junit4] 2> 151170 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 151171 T521 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 151171 T521 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370111251537
[junit4:junit4] 2> 151171 T521 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370111251537/solr.xml
[junit4:junit4] 2> 151172 T521 oasc.CoreContainer.<init> New CoreContainer 24657976
[junit4:junit4] 2> 151172 T521 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370111251537/'
[junit4:junit4] 2> 151173 T521 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370111251537/'
[junit4:junit4] 2> 151240 T521 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 151241 T521 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 151241 T521 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 151241 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 151242 T521 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 151242 T521 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 151242 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 151243 T521 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 151243 T521 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 151244 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 151246 T521 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 151247 T521 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:41168/solr
[junit4:junit4] 2> 151247 T521 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 151248 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 151249 T593 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f457c8 name:ZooKeeperConnection Watcher:127.0.0.1:41168 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 151250 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 151251 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 151254 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 151255 T595 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19c8dff name:ZooKeeperConnection Watcher:127.0.0.1:41168/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 151256 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 151258 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 152261 T521 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39997_
[junit4:junit4] 2> 152263 T521 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39997_
[junit4:junit4] 2> 152265 T550 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> 152265 T543 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> 152266 T563 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 152266 T579 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 152266 T579 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> 152266 T563 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> 152267 T595 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 152268 T550 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 152268 T543 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 152278 T596 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370111251537/collection1
[junit4:junit4] 2> 152278 T596 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 152281 T596 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 152282 T596 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 152283 T596 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370111251537/collection1/'
[junit4:junit4] 2> 152284 T596 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370111251537/collection1/lib/README' to classloader
[junit4:junit4] 2> 152285 T596 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370111251537/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 152350 T596 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 152431 T596 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 152435 T596 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 152442 T596 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 152537 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 152538 T544 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:49057__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:49057_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49057"}
[junit4:junit4] 2> 152543 T595 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> 152544 T543 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> 152543 T550 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> 152543 T563 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> 152543 T579 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> 152936 T596 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 152941 T596 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 152944 T596 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 152951 T596 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 152989 T596 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 152990 T596 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370111251537/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty3/
[junit4:junit4] 2> 152990 T596 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@b1cd0
[junit4:junit4] 2> 152991 T596 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 152992 T596 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty3
[junit4:junit4] 2> 152993 T596 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty3/index/
[junit4:junit4] 2> 152993 T596 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 152993 T596 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty3/index
[junit4:junit4] 2> 153001 T596 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ee869a lockFactory=org.apache.lucene.store.NativeFSLockFactory@16af14d),segFN=segments_1,generation=1}
[junit4:junit4] 2> 153002 T596 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 153004 T596 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 153004 T596 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 153005 T596 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 153005 T596 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 153006 T596 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 153007 T596 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 153008 T596 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 153009 T596 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 153009 T596 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 153012 T596 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 153019 T596 oass.SolrIndexSearcher.<init> Opening Searcher@4f3e0c main
[junit4:junit4] 2> 153020 T596 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty3/tlog
[junit4:junit4] 2> 153021 T596 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 153021 T596 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 153030 T596 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 153030 T597 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4f3e0c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 153030 T596 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 154051 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 154052 T544 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:39997_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39997"}
[junit4:junit4] 2> 154053 T544 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 154053 T544 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 154057 T550 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> 154058 T543 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> 154057 T595 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> 154057 T579 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> 154057 T563 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> 155035 T596 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 155035 T596 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39997 collection:collection1 shard:shard1
[junit4:junit4] 2> 155038 T596 oasc.ZkController.register We are http://127.0.0.1:39997/collection1/ and leader is http://127.0.0.1:36381/collection1/
[junit4:junit4] 2> 155038 T596 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39997
[junit4:junit4] 2> 155039 T596 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 155039 T596 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> 155044 T596 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C138 name=collection1 org.apache.solr.core.SolrCore@10fcfe5 url=http://127.0.0.1:39997/collection1 node=127.0.0.1:39997_ C138_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:39997_, base_url=http://127.0.0.1:39997}
[junit4:junit4] 2> 155045 T598 C138 P39997 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 155047 T521 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 155049 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 155048 T598 C138 P39997 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 155049 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 155049 T598 C138 P39997 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 155050 T598 C138 P39997 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 155055 T598 C138 P39997 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 155069 T558 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:39997__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 155166 T521 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 155186 T521 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:43908
[junit4:junit4] 2> 155187 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 155187 T521 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 155188 T521 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370111255495
[junit4:junit4] 2> 155189 T521 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370111255495/solr.xml
[junit4:junit4] 2> 155189 T521 oasc.CoreContainer.<init> New CoreContainer 29884522
[junit4:junit4] 2> 155190 T521 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370111255495/'
[junit4:junit4] 2> 155191 T521 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370111255495/'
[junit4:junit4] 2> 155267 T521 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 155268 T521 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 155269 T521 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 155269 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 155270 T521 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 155270 T521 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 155271 T521 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 155271 T521 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 155271 T521 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 155272 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 155275 T521 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 155275 T521 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:41168/solr
[junit4:junit4] 2> 155276 T521 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 155277 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 155278 T610 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8ed7c0 name:ZooKeeperConnection Watcher:127.0.0.1:41168 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 155279 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 155281 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 155284 T521 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 155285 T612 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17ce10d name:ZooKeeperConnection Watcher:127.0.0.1:41168/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 155286 T521 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 155289 T521 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 155564 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 155565 T544 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39997__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:39997_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39997"}
[junit4:junit4] 2> 155569 T543 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> 155569 T563 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> 155569 T550 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> 155569 T595 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> 155569 T612 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> 155569 T579 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> 156070 T558 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:39997__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 156070 T558 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:39997__collection1&state=recovering&nodeName=127.0.0.1:39997_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 156293 T521 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43908_
[junit4:junit4] 2> 156295 T521 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43908_
[junit4:junit4] 2> 156296 T543 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> 156296 T595 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> 156296 T612 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> 156297 T579 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 156297 T563 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 156297 T550 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> 156298 T543 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 156298 T563 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> 156297 T579 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> 156298 T595 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 156299 T550 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 156301 T612 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 156305 T613 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370111255495/collection1
[junit4:junit4] 2> 156305 T613 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 156306 T613 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 156306 T613 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 156307 T613 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370111255495/collection1/'
[junit4:junit4] 2> 156307 T613 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370111255495/collection1/lib/README' to classloader
[junit4:junit4] 2> 156308 T613 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370111255495/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 156339 T613 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 156384 T613 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 156385 T613 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 156389 T613 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 156776 T613 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 156779 T613 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 156780 T613 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 156784 T613 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 156800 T613 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 156801 T613 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370111255495/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/
[junit4:junit4] 2> 156801 T613 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@b1cd0
[junit4:junit4] 2> 156801 T613 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 156802 T613 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4
[junit4:junit4] 2> 156802 T613 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/index/
[junit4:junit4] 2> 156802 T613 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 156803 T613 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/index
[junit4:junit4] 2> 156804 T613 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e61b85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@959a06),segFN=segments_1,generation=1}
[junit4:junit4] 2> 156804 T613 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 156806 T613 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 156806 T613 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 156807 T613 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 156808 T613 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 156808 T613 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 156809 T613 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 156809 T613 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 156810 T613 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 156811 T613 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 156814 T613 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 156818 T613 oass.SolrIndexSearcher.<init> Opening Searcher@4029df main
[junit4:junit4] 2> 156818 T613 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/tlog
[junit4:junit4] 2> 156819 T613 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 156819 T613 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 156827 T614 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4029df main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 156829 T613 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 156829 T613 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 157073 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 157073 T544 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:43908_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43908"}
[junit4:junit4] 2> 157074 T544 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 157074 T544 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 157077 T543 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> 157077 T550 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> 157077 T579 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> 157077 T595 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> 157077 T612 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> 157077 T563 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> 157830 T613 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 157831 T613 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43908 collection:collection1 shard:shard2
[junit4:junit4] 2> 157836 T613 oasc.ZkController.register We are http://127.0.0.1:43908/collection1/ and leader is http://127.0.0.1:49057/collection1/
[junit4:junit4] 2> 157836 T613 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43908
[junit4:junit4] 2> 157837 T613 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 157837 T613 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C139 name=collection1 org.apache.solr.core.SolrCore@b48c url=http://127.0.0.1:43908/collection1 node=127.0.0.1:43908_ C139_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:43908_, base_url=http://127.0.0.1:43908}
[junit4:junit4] 2> 157838 T615 C139 P43908 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 157838 T613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 157838 T615 C139 P43908 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 157839 T615 C139 P43908 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 157840 T615 C139 P43908 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 157840 T521 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 157841 T521 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 157841 T615 C139 P43908 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 157842 T521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 157848 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 157849 T572 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:43908__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 157850 T521 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 157851 T521 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 157852 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C140 name=collection1 org.apache.solr.core.SolrCore@10fcfe5 url=http://127.0.0.1:39997/collection1 node=127.0.0.1:39997_ C140_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:39997_, base_url=http://127.0.0.1:39997}
[junit4:junit4] 2> 158072 T598 C140 P39997 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:36381/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 158073 T598 C140 P39997 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:39997 START replicas=[http://127.0.0.1:36381/collection1/] nUpdates=100
[junit4:junit4] 2> 158073 T598 C140 P39997 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 158074 T598 C140 P39997 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 158074 T598 C140 P39997 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 158075 T598 C140 P39997 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 158075 T598 C140 P39997 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 158076 T598 C140 P39997 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:36381/collection1/. core=collection1
[junit4:junit4] 2> 158076 T598 C140 P39997 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C141 name=collection1 org.apache.solr.core.SolrCore@3e4d7a url=http://127.0.0.1:36381/collection1 node=127.0.0.1:36381_ C141_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:36381_, base_url=http://127.0.0.1:36381, leader=true}
[junit4:junit4] 2> 158088 T559 C141 P36381 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> 158094 T557 C141 P36381 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 158097 T557 C141 P36381 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@cb88c8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fa8450),segFN=segments_1,generation=1}
[junit4:junit4] 2> 158098 T557 C141 P36381 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 158099 T557 C141 P36381 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@cb88c8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fa8450),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@cb88c8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fa8450),segFN=segments_2,generation=2}
[junit4:junit4] 2> 158100 T557 C141 P36381 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 158101 T557 C141 P36381 oass.SolrIndexSearcher.<init> Opening Searcher@5a35d8 realtime
[junit4:junit4] 2> 158101 T557 C141 P36381 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 158102 T557 C141 P36381 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 8
[junit4:junit4] 2> 158103 T598 C140 P39997 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 158104 T598 C140 P39997 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 158106 T559 C141 P36381 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 158107 T559 C141 P36381 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 158108 T598 C140 P39997 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 158108 T598 C140 P39997 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 158109 T598 C140 P39997 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 158111 T557 C141 P36381 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> 158112 T598 C140 P39997 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 158113 T598 C140 P39997 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty3/index.20130601132738554
[junit4:junit4] 2> 158114 T598 C140 P39997 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@167a465 lockFactory=org.apache.lucene.store.NativeFSLockFactory@90f4fb) fullCopy=false
[junit4:junit4] 2> 158117 T556 C141 P36381 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> 158119 T598 C140 P39997 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 158121 T598 C140 P39997 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 158121 T598 C140 P39997 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 158123 T598 C140 P39997 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ee869a lockFactory=org.apache.lucene.store.NativeFSLockFactory@16af14d),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ee869a lockFactory=org.apache.lucene.store.NativeFSLockFactory@16af14d),segFN=segments_2,generation=2}
[junit4:junit4] 2> 158124 T598 C140 P39997 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 158124 T598 C140 P39997 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 158125 T598 C140 P39997 oass.SolrIndexSearcher.<init> Opening Searcher@e5477 main
[junit4:junit4] 2> 158127 T597 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e5477 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 158128 T598 C140 P39997 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty3/index.20130601132738554 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty3/index.20130601132738554;done=true>>]
[junit4:junit4] 2> 158129 T598 C140 P39997 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty3/index.20130601132738554
[junit4:junit4] 2> 158129 T598 C140 P39997 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty3/index.20130601132738554
[junit4:junit4] 2> 158130 T598 C140 P39997 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 158130 T598 C140 P39997 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 158130 T598 C140 P39997 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 158131 T598 C140 P39997 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 158133 T598 C140 P39997 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 158581 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 158582 T544 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43908__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:43908_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43908"}
[junit4:junit4] 2> 158584 T544 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39997__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:39997_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39997"}
[junit4:junit4] 2> 158587 T543 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> 158587 T563 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> 158587 T579 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> 158587 T595 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> 158587 T550 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> 158587 T612 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> 158850 T572 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:43908__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 158851 T572 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:43908__collection1&state=recovering&nodeName=127.0.0.1:43908_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 158854 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 159856 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C139_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:43908_, base_url=http://127.0.0.1:43908}
[junit4:junit4] 2> 160852 T615 C139 P43908 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49057/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 160852 T615 C139 P43908 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:43908 START replicas=[http://127.0.0.1:49057/collection1/] nUpdates=100
[junit4:junit4] 2> 160853 T615 C139 P43908 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 160853 T615 C139 P43908 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 160853 T615 C139 P43908 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 160854 T615 C139 P43908 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 160854 T615 C139 P43908 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 160854 T615 C139 P43908 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49057/collection1/. core=collection1
[junit4:junit4] 2> 160854 T615 C139 P43908 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 160858 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C142 name=collection1 org.apache.solr.core.SolrCore@1278338 url=http://127.0.0.1:49057/collection1 node=127.0.0.1:49057_ C142_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49057_, base_url=http://127.0.0.1:49057, leader=true}
[junit4:junit4] 2> 160859 T573 C142 P49057 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> 160859 T575 C142 P49057 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 160862 T575 C142 P49057 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@213dbd lockFactory=org.apache.lucene.store.NativeFSLockFactory@88a142),segFN=segments_1,generation=1}
[junit4:junit4] 2> 160863 T575 C142 P49057 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 160864 T575 C142 P49057 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@213dbd lockFactory=org.apache.lucene.store.NativeFSLockFactory@88a142),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@213dbd lockFactory=org.apache.lucene.store.NativeFSLockFactory@88a142),segFN=segments_2,generation=2}
[junit4:junit4] 2> 160865 T575 C142 P49057 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 160865 T575 C142 P49057 oass.SolrIndexSearcher.<init> Opening Searcher@66b1f4 realtime
[junit4:junit4] 2> 160866 T575 C142 P49057 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 160866 T575 C142 P49057 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 7
[junit4:junit4] 2> 160867 T615 C139 P43908 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 160867 T615 C139 P43908 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 160869 T574 C142 P49057 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 160869 T574 C142 P49057 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 160870 T615 C139 P43908 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 160870 T615 C139 P43908 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 160870 T615 C139 P43908 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 160872 T573 C142 P49057 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> 160873 T615 C139 P43908 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 160873 T615 C139 P43908 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/index.20130601132741315
[junit4:junit4] 2> 160874 T615 C139 P43908 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@14336e4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e1e5d7) fullCopy=false
[junit4:junit4] 2> 160876 T575 C142 P49057 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> 160877 T615 C139 P43908 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 160878 T615 C139 P43908 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 160878 T615 C139 P43908 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 160879 T615 C139 P43908 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e61b85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@959a06),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e61b85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@959a06),segFN=segments_2,generation=2}
[junit4:junit4] 2> 160880 T615 C139 P43908 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 160880 T615 C139 P43908 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 160880 T615 C139 P43908 oass.SolrIndexSearcher.<init> Opening Searcher@281111 main
[junit4:junit4] 2> 160882 T614 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@281111 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 160882 T615 C139 P43908 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/index.20130601132741315 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/index.20130601132741315;done=true>>]
[junit4:junit4] 2> 160883 T615 C139 P43908 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/index.20130601132741315
[junit4:junit4] 2> 160883 T615 C139 P43908 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/index.20130601132741315
[junit4:junit4] 2> 160883 T615 C139 P43908 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 160883 T615 C139 P43908 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 160883 T615 C139 P43908 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 160883 T615 C139 P43908 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 160884 T615 C139 P43908 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 161596 T544 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 161598 T544 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43908__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:43908_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43908"}
[junit4:junit4] 2> 161603 T543 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> 161603 T595 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> 161603 T579 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> 161603 T612 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> 161603 T550 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> 161603 T563 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> 161860 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 161862 T521 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C143 name=collection1 org.apache.solr.core.SolrCore@133e2b3 url=http://127.0.0.1:50022/collection1 node=127.0.0.1:50022_ C143_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:50022_, base_url=http://127.0.0.1:50022, leader=true}
[junit4:junit4] 2> 161874 T538 C143 P50022 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 161877 T538 C143 P50022 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1d4bee1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e643a7),segFN=segments_1,generation=1}
[junit4:junit4] 2> 161878 T538 C143 P50022 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 161879 T538 C143 P50022 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1d4bee1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e643a7),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1d4bee1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e643a7),segFN=segments_2,generation=2}
[junit4:junit4] 2> 161880 T538 C143 P50022 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 161881 T538 C143 P50022 oass.SolrIndexSearcher.<init> Opening Searcher@183890e main
[junit4:junit4] 2> 161882 T538 C143 P50022 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 161884 T547 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@183890e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 161885 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> 161892 T572 C142 P49057 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 161894 T572 C142 P49057 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@213dbd lockFactory=org.apache.lucene.store.NativeFSLockFactory@88a142),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@213dbd lockFactory=org.apache.lucene.store.NativeFSLockFactory@88a142),segFN=segments_3,generation=3}
[junit4:junit4] 2> 161895 T572 C142 P49057 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 161895 T572 C142 P49057 oass.SolrIndexSearcher.<init> Opening Searcher@7d9873 main
[junit4:junit4] 2> 161896 T572 C142 P49057 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 161898 T581 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7d9873 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 161900 T572 C142 P49057 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:36381/collection1/, StdNode: http://127.0.0.1:39997/collection1/, StdNode: http://127.0.0.1:43908/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 161908 T558 C141 P36381 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 161915 T558 C141 P36381 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@cb88c8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fa8450),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@cb88c8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fa8450),segFN=segments_3,generation=3}
[junit4:junit4] 2> 161916 T558 C141 P36381 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 161919 T558 C141 P36381 oass.SolrIndexSearcher.<init> Opening Searcher@58c90f main
[junit4:junit4] 2> 161920 T558 C141 P36381 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> C140_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:39997_, base_url=http://127.0.0.1:39997}
[junit4:junit4] 2> 161921 T588 C140 P39997 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C139_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43908_, base_url=http://127.0.0.1:43908}
[junit4:junit4] 2> 161922 T608 C139 P43908 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 161923 T588 C140 P39997 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ee869a lockFactory=org.apache.lucene.store.NativeFSLockFactory@16af14d),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ee869a lockFactory=org.apache.lucene.store.NativeFSLockFactory@16af14d),segFN=segments_3,generation=3}
[junit4:junit4] 2> 161923 T565 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@58c90f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 161925 T588 C140 P39997 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 161924 T608 C139 P43908 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e61b85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@959a06),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e61b85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@959a06),segFN=segments_3,generation=3}
[junit4:junit4] 2> 161926 T588 C140 P39997 oass.SolrIndexSearcher.<init> Opening Searcher@75b901 main
[junit4:junit4] 2> 161926 T558 C141 P36381 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 18
[junit4:junit4] 2> 161928 T588 C140 P39997 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 161927 T608 C139 P43908 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 161930 T597 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@75b901 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 161930 T608 C139 P43908 oass.SolrIndexSearcher.<init> Opening Searcher@11b7787 main
[junit4:junit4] 2> 161932 T608 C139 P43908 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 161931 T588 C140 P39997 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 10
[junit4:junit4] 2> 161934 T614 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@11b7787 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 161935 T608 C139 P43908 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 13
[junit4:junit4] 2> 161936 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 44
[junit4:junit4] 2> 161938 T521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 161942 T559 C141 P36381 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> 161945 T590 C140 P39997 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> 161947 T574 C142 P49057 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> 161950 T605 C139 P43908 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> 163957 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436665789176348672)} 0 3
[junit4:junit4] 2> 163963 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436665789180542976&update.from=http://127.0.0.1:36381/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436665789180542976)} 0 1
[junit4:junit4] 2> 163966 T605 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436665789184737280&update.from=http://127.0.0.1:49057/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436665789184737280)} 0 1
[junit4:junit4] 2> 163967 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1436665789184737280)} 0 5
[junit4:junit4] 2> 163968 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436665789180542976)} 0 9
[junit4:junit4] 2> 163972 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1436665789193125888)]} 0 1
[junit4:junit4] 2> 163978 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1436665789197320192)]} 0 1
[junit4:junit4] 2> 163979 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1436665789197320192)]} 0 4
[junit4:junit4] 2> 163983 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1436665789204660224)]} 0 1
[junit4:junit4] 2> 163991 T588 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1436665789210951680)]} 0 1
[junit4:junit4] 2> 163992 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1436665789210951680)]} 0 4
[junit4:junit4] 2> 163993 T574 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1]} 0 8
[junit4:junit4] 2> 163996 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1436665789219340288)]} 0 0
[junit4:junit4] 2> 164002 T606 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1436665789222486016)]} 0 1
[junit4:junit4] 2> 164003 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1436665789222486016)]} 0 4
[junit4:junit4] 2> 164006 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1436665789229826048)]} 0 0
[junit4:junit4] 2> 164012 T607 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1436665789232971776)]} 0 1
[junit4:junit4] 2> 164013 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1436665789232971776)]} 0 4
[junit4:junit4] 2> 164016 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1436665789240311808)]} 0 0
[junit4:junit4] 2> 164024 T589 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1436665789245554688)]} 0 0
[junit4:junit4] 2> 164025 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1436665789245554688)]} 0 4
[junit4:junit4] 2> 164026 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4]} 0 7
[junit4:junit4] 2> 164029 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1436665789253943296)]} 0 0
[junit4:junit4] 2> 164037 T608 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1436665789259186176)]} 0 1
[junit4:junit4] 2> 164038 T574 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1436665789259186176)]} 0 4
[junit4:junit4] 2> 164039 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5]} 0 7
[junit4:junit4] 2> 164042 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1436665789267574784)]} 0 0
[junit4:junit4] 2> 164047 T605 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1436665789270720512)]} 0 0
[junit4:junit4] 2> 164049 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1436665789270720512)]} 0 4
[junit4:junit4] 2> 164052 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1436665789277011968)]} 0 1
[junit4:junit4] 2> 164060 T606 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1436665789283303424)]} 0 1
[junit4:junit4] 2> 164061 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1436665789283303424)]} 0 4
[junit4:junit4] 2> 164062 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7]} 0 8
[junit4:junit4] 2> 164065 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1436665789291692032)]} 0 1
[junit4:junit4] 2> 164073 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1436665789296934912)]} 0 1
[junit4:junit4] 2> 164074 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1436665789296934912)]} 0 4
[junit4:junit4] 2> 164075 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8]} 0 7
[junit4:junit4] 2> 164078 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1436665789305323520)]} 0 0
[junit4:junit4] 2> 164086 T607 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1436665789310566400)]} 0 0
[junit4:junit4] 2> 164087 T574 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[9 (1436665789310566400)]} 0 4
[junit4:junit4] 2> 164088 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9]} 0 7
[junit4:junit4] 2> 164091 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1436665789318955008)]} 0 0
[junit4:junit4] 2> 164097 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1436665789322100736)]} 0 1
[junit4:junit4] 2> 164098 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1436665789322100736)]} 0 4
[junit4:junit4] 2> 164101 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1436665789329440768)]} 0 0
[junit4:junit4] 2> 164108 T588 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1436665789334683648)]} 0 0
[junit4:junit4] 2> 164110 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1436665789334683648)]} 0 4
[junit4:junit4] 2> 164111 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11]} 0 7
[junit4:junit4] 2> 164114 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1436665789342023680)]} 0 1
[junit4:junit4] 2> 164119 T589 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1436665789345169408)]} 0 0
[junit4:junit4] 2> 164120 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1436665789345169408)]} 0 4
[junit4:junit4] 2> 164123 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1436665789352509440)]} 0 0
[junit4:junit4] 2> 164129 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1436665789355655168)]} 0 0
[junit4:junit4] 2> 164130 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1436665789355655168)]} 0 4
[junit4:junit4] 2> 164133 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1436665789362995200)]} 0 0
[junit4:junit4] 2> 164139 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1436665789366140928)]} 0 0
[junit4:junit4] 2> 164140 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1436665789366140928)]} 0 4
[junit4:junit4] 2> 164143 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1436665789373480960)]} 0 0
[junit4:junit4] 2> 164151 T588 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1436665789378723840)]} 0 0
[junit4:junit4] 2> 164152 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1436665789378723840)]} 0 4
[junit4:junit4] 2> 164153 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15]} 0 7
[junit4:junit4] 2> 164156 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1436665789387112448)]} 0 0
[junit4:junit4] 2> 164164 T589 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1436665789392355328)]} 0 1
[junit4:junit4] 2> 164165 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1436665789392355328)]} 0 4
[junit4:junit4] 2> 164166 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16]} 0 7
[junit4:junit4] 2> 164169 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1436665789400743936)]} 0 1
[junit4:junit4] 2> 164174 T608 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1436665789403889664)]} 0 0
[junit4:junit4] 2> 164175 T574 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1436665789403889664)]} 0 4
[junit4:junit4] 2> 164178 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1436665789410181120)]} 0 0
[junit4:junit4] 2> 164186 T605 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1436665789416472576)]} 0 0
[junit4:junit4] 2> 164187 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1436665789416472576)]} 0 4
[junit4:junit4] 2> 164188 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18]} 0 7
[junit4:junit4] 2> 164191 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1436665789423812608)]} 0 0
[junit4:junit4] 2> 164199 T606 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1436665789429055488)]} 0 1
[junit4:junit4] 2> 164200 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1436665789429055488)]} 0 4
[junit4:junit4] 2> 164201 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19]} 0 7
[junit4:junit4] 2> 164204 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1436665789436395520)]} 0 1
[junit4:junit4] 2> 164209 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1436665789439541248)]} 0 0
[junit4:junit4] 2> 164210 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1436665789439541248)]} 0 4
[junit4:junit4] 2> 164213 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1436665789446881280)]} 0 0
[junit4:junit4] 2> 164218 T607 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1436665789450027008)]} 0 0
[junit4:junit4] 2> 164219 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1436665789450027008)]} 0 3
[junit4:junit4] 2> 164223 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1436665789456318464)]} 0 1
[junit4:junit4] 2> 164228 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1436665789459464192)]} 0 0
[junit4:junit4] 2> 164229 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1436665789459464192)]} 0 4
[junit4:junit4] 2> 164232 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1436665789466804224)]} 0 0
[junit4:junit4] 2> 164240 T608 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1436665789472047104)]} 0 0
[junit4:junit4] 2> 164241 T574 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[23 (1436665789472047104)]} 0 4
[junit4:junit4] 2> 164242 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23]} 0 7
[junit4:junit4] 2> 164245 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1436665789480435712)]} 0 0
[junit4:junit4] 2> 164250 T588 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1436665789483581440)]} 0 0
[junit4:junit4] 2> 164251 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1436665789483581440)]} 0 3
[junit4:junit4] 2> 164255 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1436665789489872896)]} 0 1
[junit4:junit4] 2> 164260 T605 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1436665789494067200)]} 0 0
[junit4:junit4] 2> 164261 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1436665789494067200)]} 0 3
[junit4:junit4] 2> 164265 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1436665789500358656)]} 0 1
[junit4:junit4] 2> 164270 T606 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1436665789503504384)]} 0 0
[junit4:junit4] 2> 164271 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1436665789503504384)]} 0 4
[junit4:junit4] 2> 164274 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1436665789510844416)]} 0 0
[junit4:junit4] 2> 164280 T589 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1436665789513990144)]} 0 0
[junit4:junit4] 2> 164281 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1436665789513990144)]} 0 4
[junit4:junit4] 2> 164284 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1436665789521330176)]} 0 0
[junit4:junit4] 2> 164292 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1436665789527621632)]} 0 0
[junit4:junit4] 2> 164293 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[28 (1436665789527621632)]} 0 4
[junit4:junit4] 2> 164294 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28]} 0 7
[junit4:junit4] 2> 164297 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1436665789534961664)]} 0 0
[junit4:junit4] 2> 164305 T607 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1436665789540204544)]} 0 1
[junit4:junit4] 2> 164306 T574 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1436665789540204544)]} 0 4
[junit4:junit4] 2> 164307 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29]} 0 7
[junit4:junit4] 2> 164310 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1436665789548593152)]} 0 0
[junit4:junit4] 2> 164318 T608 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1436665789553836032)]} 0 1
[junit4:junit4] 2> 164319 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1436665789553836032)]} 0 4
[junit4:junit4] 2> 164320 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30]} 0 7
[junit4:junit4] 2> 164323 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1436665789562224640)]} 0 1
[junit4:junit4] 2> 164328 T605 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1436665789565370368)]} 0 0
[junit4:junit4] 2> 164329 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1436665789565370368)]} 0 3
[junit4:junit4] 2> 164333 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1436665789571661824)]} 0 1
[junit4:junit4] 2> 164340 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1436665789577953280)]} 0 0
[junit4:junit4] 2> 164342 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[32 (1436665789577953280)]} 0 4
[junit4:junit4] 2> 164343 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32]} 0 7
[junit4:junit4] 2> 164346 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1436665789586341888)]} 0 0
[junit4:junit4] 2> 164354 T606 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1436665789591584768)]} 0 1
[junit4:junit4] 2> 164355 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[33 (1436665789591584768)]} 0 4
[junit4:junit4] 2> 164356 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33]} 0 7
[junit4:junit4] 2> 164359 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1436665789599973376)]} 0 0
[junit4:junit4] 2> 164366 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1436665789604167680)]} 0 1
[junit4:junit4] 2> 164367 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1436665789604167680)]} 0 4
[junit4:junit4] 2> 164370 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1436665789611507712)]} 0 0
[junit4:junit4] 2> 164378 T588 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1436665789616750592)]} 0 0
[junit4:junit4] 2> 164379 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[35 (1436665789616750592)]} 0 4
[junit4:junit4] 2> 164380 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35]} 0 7
[junit4:junit4] 2> 164383 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1436665789625139200)]} 0 0
[junit4:junit4] 2> 164389 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1436665789628284928)]} 0 1
[junit4:junit4] 2> 164390 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1436665789628284928)]} 0 4
[junit4:junit4] 2> 164393 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1436665789635624960)]} 0 1
[junit4:junit4] 2> 164400 T605 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1436665789640867840)]} 0 0
[junit4:junit4] 2> 164401 T574 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[37 (1436665789640867840)]} 0 3
[junit4:junit4] 2> 164403 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37]} 0 7
[junit4:junit4] 2> 164406 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1436665789648207872)]} 0 1
[junit4:junit4] 2> 164413 T589 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1436665789654499328)]} 0 0
[junit4:junit4] 2> 164414 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[38 (1436665789654499328)]} 0 3
[junit4:junit4] 2> 164415 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38]} 0 7
[junit4:junit4] 2> 164418 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1436665789661839360)]} 0 0
[junit4:junit4] 2> 164426 T607 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1436665789668130816)]} 0 0
[junit4:junit4] 2> 164427 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[39 (1436665789668130816)]} 0 4
[junit4:junit4] 2> 164428 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39]} 0 7
[junit4:junit4] 2> 164431 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1436665789675470848)]} 0 0
[junit4:junit4] 2> 164439 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1436665789681762304)]} 0 0
[junit4:junit4] 2> 164440 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[40 (1436665789681762304)]} 0 4
[junit4:junit4] 2> 164441 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40]} 0 7
[junit4:junit4] 2> 164444 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1436665789689102336)]} 0 0
[junit4:junit4] 2> 164452 T588 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1436665789694345216)]} 0 1
[junit4:junit4] 2> 164453 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[41 (1436665789694345216)]} 0 4
[junit4:junit4] 2> 164454 T574 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41]} 0 7
[junit4:junit4] 2> 164457 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1436665789702733824)]} 0 1
[junit4:junit4] 2> 164464 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1436665789707976704)]} 0 0
[junit4:junit4] 2> 164465 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[42 (1436665789707976704)]} 0 3
[junit4:junit4] 2> 164466 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42]} 0 7
[junit4:junit4] 2> 164469 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1436665789715316736)]} 0 0
[junit4:junit4] 2> 164475 T589 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1436665789718462464)]} 0 1
[junit4:junit4] 2> 164476 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1436665789718462464)]} 0 4
[junit4:junit4] 2> 164479 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1436665789725802496)]} 0 0
[junit4:junit4] 2> 164484 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1436665789728948224)]} 0 0
[junit4:junit4] 2> 164485 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1436665789728948224)]} 0 3
[junit4:junit4] 2> 164489 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1436665789736288256)]} 0 1
[junit4:junit4] 2> 164496 T608 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1436665789741531136)]} 0 0
[junit4:junit4] 2> 164497 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[45 (1436665789741531136)]} 0 3
[junit4:junit4] 2> 164498 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45]} 0 6
[junit4:junit4] 2> 164501 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1436665789748871168)]} 0 0
[junit4:junit4] 2> 164507 T588 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1436665789752016896)]} 0 0
[junit4:junit4] 2> 164508 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1436665789752016896)]} 0 4
[junit4:junit4] 2> 164511 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1436665789759356928)]} 0 0
[junit4:junit4] 2> 164518 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1436665789764599808)]} 0 0
[junit4:junit4] 2> 164519 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[47 (1436665789764599808)]} 0 3
[junit4:junit4] 2> 164520 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47]} 0 6
[junit4:junit4] 2> 164523 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1436665789771939840)]} 0 0
[junit4:junit4] 2> 164529 T589 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1436665789775085568)]} 0 0
[junit4:junit4] 2> 164530 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1436665789775085568)]} 0 4
[junit4:junit4] 2> 164534 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1436665789782425600)]} 0 1
[junit4:junit4] 2> 164541 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1436665789788717056)]} 0 0
[junit4:junit4] 2> 164542 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[49 (1436665789788717056)]} 0 4
[junit4:junit4] 2> 164543 T574 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49]} 0 7
[junit4:junit4] 2> 164548 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1436665789797105664)]} 0 2
[junit4:junit4] 2> 164555 T588 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1436665789803397120)]} 0 0
[junit4:junit4] 2> 164556 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[50 (1436665789803397120)]} 0 3
[junit4:junit4] 2> 164557 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50]} 0 7
[junit4:junit4] 2> 164560 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1436665789810737152)]} 0 0
[junit4:junit4] 2> 164566 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1436665789813882880)]} 0 0
[junit4:junit4] 2> 164567 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1436665789813882880)]} 0 4
[junit4:junit4] 2> 164570 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1436665789821222912)]} 0 0
[junit4:junit4] 2> 164576 T589 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1436665789824368640)]} 0 1
[junit4:junit4] 2> 164577 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1436665789824368640)]} 0 4
[junit4:junit4] 2> 164580 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1436665789830660096)]} 0 1
[junit4:junit4] 2> 164587 T606 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1436665789836951552)]} 0 0
[junit4:junit4] 2> 164588 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1436665789836951552)]} 0 3
[junit4:junit4] 2> 164589 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53]} 0 7
[junit4:junit4] 2> 164593 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1436665789844291584)]} 0 1
[junit4:junit4] 2> 164600 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1436665789850583040)]} 0 0
[junit4:junit4] 2> 164601 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[54 (1436665789850583040)]} 0 4
[junit4:junit4] 2> 164602 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54]} 0 7
[junit4:junit4] 2> 164605 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1436665789857923072)]} 0 0
[junit4:junit4] 2> 164613 T588 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1436665789863165952)]} 0 1
[junit4:junit4] 2> 164614 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[55 (1436665789863165952)]} 0 4
[junit4:junit4] 2> 164614 T574 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55]} 0 6
[junit4:junit4] 2> 164618 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1436665789870505984)]} 0 1
[junit4:junit4] 2> 164623 T605 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1436665789874700288)]} 0 0
[junit4:junit4] 2> 164624 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1436665789874700288)]} 0 4
[junit4:junit4] 2> 164627 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1436665789880991744)]} 0 0
[junit4:junit4] 2> 164635 T607 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1436665789886234624)]} 0 1
[junit4:junit4] 2> 164636 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[57 (1436665789886234624)]} 0 4
[junit4:junit4] 2> 164637 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57]} 0 7
[junit4:junit4] 2> 164640 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1436665789894623232)]} 0 1
[junit4:junit4] 2> 164645 T608 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1436665789897768960)]} 0 0
[junit4:junit4] 2> 164646 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1436665789897768960)]} 0 3
[junit4:junit4] 2> 164650 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1436665789904060416)]} 0 1
[junit4:junit4] 2> 164655 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1436665789908254720)]} 0 0
[junit4:junit4] 2> 164656 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1436665789908254720)]} 0 4
[junit4:junit4] 2> 164659 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1436665789914546176)]} 0 0
[junit4:junit4] 2> 164667 T606 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1436665789920837632)]} 0 0
[junit4:junit4] 2> 164669 T574 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[60 (1436665789920837632)]} 0 4
[junit4:junit4] 2> 164670 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60]} 0 8
[junit4:junit4] 2> 164673 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1436665789928177664)]} 0 1
[junit4:junit4] 2> 164678 T589 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1436665789932371968)]} 0 0
[junit4:junit4] 2> 164680 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1436665789932371968)]} 0 5
[junit4:junit4] 2> 164683 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1436665789939712000)]} 0 1
[junit4:junit4] 2> 164688 T605 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1436665789942857728)]} 0 0
[junit4:junit4] 2> 164689 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1436665789942857728)]} 0 3
[junit4:junit4] 2> 164693 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1436665789949149184)]} 0 1
[junit4:junit4] 2> 164700 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1436665789955440640)]} 0 0
[junit4:junit4] 2> 164701 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[63 (1436665789955440640)]} 0 3
[junit4:junit4] 2> 164702 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63]} 0 7
[junit4:junit4] 2> 164706 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1436665789963829248)]} 0 0
[junit4:junit4] 2> 164712 T588 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1436665789966974976)]} 0 1
[junit4:junit4] 2> 164713 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1436665789966974976)]} 0 4
[junit4:junit4] 2> 164716 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1436665789974315008)]} 0 0
[junit4:junit4] 2> 164721 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1436665789977460736)]} 0 0
[junit4:junit4] 2> 164722 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1436665789977460736)]} 0 3
[junit4:junit4] 2> 164725 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1436665789983752192)]} 0 0
[junit4:junit4] 2> 164731 T589 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1436665789986897920)]} 0 1
[junit4:junit4] 2> 164732 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1436665789986897920)]} 0 4
[junit4:junit4] 2> 164735 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1436665789994237952)]} 0 0
[junit4:junit4] 2> 164743 T607 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1436665789999480832)]} 0 1
[junit4:junit4] 2> 164744 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[67 (1436665789999480832)]} 0 4
[junit4:junit4] 2> 164745 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67]} 0 7
[junit4:junit4] 2> 164748 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1436665790007869440)]} 0 0
[junit4:junit4] 2> 164753 T608 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[68 (1436665790011015168)]} 0 0
[junit4:junit4] 2> 164754 T573 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1436665790011015168)]} 0 3
[junit4:junit4] 2> 164757 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1436665790017306624)]} 0 0
[junit4:junit4] 2> 164763 T605 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[69 (1436665790020452352)]} 0 1
[junit4:junit4] 2> 164764 T575 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1436665790020452352)]} 0 4
[junit4:junit4] 2> 164767 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1436665790027792384)]} 0 0
[junit4:junit4] 2> 164773 T590 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[70 (1436665790030938112)]} 0 1
[junit4:junit4] 2> 164774 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1436665790030938112)]} 0 4
[junit4:junit4] 2> 164777 T536 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71 (1436665790038278144)]} 0 1
[junit4:junit4] 2> 164784 T607 C139 P43908 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[71 (1436665790043521024)]} 0 0
[junit4:junit4] 2> 164785 T572 C142 P49057 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[71 (1436665790043521024)]} 0 3
[junit4:junit4] 2> 164786 T558 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71]} 0 6
[junit4:junit4] 2> 164790 T537 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1436665790050861056)]} 0 1
[junit4:junit4] 2> 164795 T591 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[72 (1436665790055055360)]} 0 0
[junit4:junit4] 2> 164796 T557 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1436665790055055360)]} 0 4
[junit4:junit4] 2> 164799 T538 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[73 (1436665790061346816)]} 0 0
[junit4:junit4] 2> 164805 T589 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[73 (1436665790064492544)]} 0 0
[junit4:junit4] 2> 164806 T556 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[73 (1436665790064492544)]} 0 4
[junit4:junit4] 2> 164809 T539 C143 P50022 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[74 (1436665790071832576)]} 0 0
[junit4:junit4] 2> 164817 T588 C140 P39997 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36381/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[74 (1436665790077075456)]} 0 1
[junit4:junit4] 2> 164818 T559 C141 P36381 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49057/collection1/&update.distrib=TOLEADER&wt=javabin&
[...truncated too long message...]
680 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 317690 T680 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39997__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[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:39997_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39997"}
[junit4:junit4] 2> 317693 T680 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39997__collection1_shard1_0_replica1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1_0",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":null,
[junit4:junit4] 2> "core":"collection1_shard1_0_replica1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:39997_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39997"}
[junit4:junit4] 2> 317695 T680 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39997__collection1_shard1_1_replica1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1_1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":null,
[junit4:junit4] 2> "core":"collection1_shard1_1_replica1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:39997_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39997"}
[junit4:junit4] 2> 317698 T612 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> 317701 T521 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 317752 T521 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 43908
[junit4:junit4] 2> 317753 T521 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=29884522
[junit4:junit4] 2> 318755 T521 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 318755 T521 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 318758 T521 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@b48c
[junit4:junit4] 2> 318760 T521 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=4,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=708,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 318761 T521 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 318762 T521 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 318762 T521 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 318764 T521 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 318765 T521 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 318766 T521 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4;done=false>>]
[junit4:junit4] 2> 318767 T521 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4
[junit4:junit4] 2> 318767 T521 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/index;done=false>>]
[junit4:junit4] 2> 318768 T521 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896/jetty4/index
[junit4:junit4] 2> 318769 T680 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89791610152484876-127.0.0.1:43908_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 318770 T612 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> 318771 T612 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 318771 T612 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 318793 T521 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 318854 T521 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 318856 T521 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:41168 41168
[junit4:junit4] 2> 318858 T521 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 50022
[junit4:junit4] 2> !!!! WARNING: best effort to remove /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370111238896 FAILED !!!!!
[junit4:junit4] 2> 318859 T521 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 318860 T521 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:41168 41168
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeyShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=E473EFEF7429C718 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=in_ID -Dtests.timezone=America/Bahia_Banderas -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 180s J0 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:36381 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([E473EFEF7429C718:659561F70376A724]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:662)
[junit4:junit4] 2> 318892 T521 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 180444 T520 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=NestedPulsing), _version_=PostingsFormat(name=Memory doPackFST= true)}, docValues:{}, sim=DefaultSimilarity, locale=in_ID, timezone=America/Bahia_Banderas
[junit4:junit4] 2> NOTE: Linux 3.2.0-45-generic i386/Sun Microsystems Inc. 1.6.0_45 (32-bit)/cpus=8,threads=2,free=168764080,total=202637312
[junit4:junit4] 2> NOTE: All tests run in this JVM: [RAMDirectoryFactoryTest, AutoCommitTest, TestBadConfig, PluginInfoTest, DirectUpdateHandlerOptimizeTest, PrimUtilsTest, BinaryUpdateRequestHandlerTest, TestGroupingSearch, DistributedSpellCheckComponentTest, SOLR749Test, TestUniqueKeyFieldResource, ShardRoutingTest, TestReloadAndDeleteDocs, SolrTestCaseJ4Test, TestFaceting, PolyFieldTest, BadComponentTest, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J0 in 181.23s, 1 test, 1 error <<< FAILURES!
[...truncated 803 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: 297 suites, 1238 tests, 1 error, 13 ignored (7 assumptions)
Total time: 42 minutes 34 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.6.0_45 -client -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.7.0_21) - Build # 5873
- Still Failing!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/5873/
Java: 32bit/jdk1.7.0_21 -client -XX:+UseSerialGC
1 tests failed.
FAILED: org.apache.lucene.spatial.prefix.SpatialOpRecursivePrefixTreeTest.testContains {#5 seed=[AEDB749B8C7ED7ED:1AAA2819BFF6214C]}
Error Message:
Shouldn't match I #0:ShapePair(Rect(minX=121.0,maxX=137.0,minY=-117.0,maxY=-109.0) , Rect(minX=124.0,maxX=129.0,minY=22.0,maxY=27.0)) Q:Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)
Stack Trace:
java.lang.AssertionError: Shouldn't match I #0:ShapePair(Rect(minX=121.0,maxX=137.0,minY=-117.0,maxY=-109.0) , Rect(minX=124.0,maxX=129.0,minY=22.0,maxY=27.0)) Q:Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)
at __randomizedtesting.SeedInfo.seed([AEDB749B8C7ED7ED:1AAA2819BFF6214C]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.lucene.spatial.prefix.SpatialOpRecursivePrefixTreeTest.fail(SpatialOpRecursivePrefixTreeTest.java:287)
at org.apache.lucene.spatial.prefix.SpatialOpRecursivePrefixTreeTest.doTest(SpatialOpRecursivePrefixTreeTest.java:273)
at org.apache.lucene.spatial.prefix.SpatialOpRecursivePrefixTreeTest.testContains(SpatialOpRecursivePrefixTreeTest.java:101)
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 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 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 8398 lines...]
[junit4:junit4] Suite: org.apache.lucene.spatial.prefix.SpatialOpRecursivePrefixTreeTest
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:2,SPG:(QuadPrefixTree(maxLevels:6,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:0,SPG:(QuadPrefixTree(maxLevels:4,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-1,SPG:(QuadPrefixTree(maxLevels:3,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:4,SPG:(QuadPrefixTree(maxLevels:8,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:4,SPG:(QuadPrefixTree(maxLevels:8,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-2,SPG:(QuadPrefixTree(maxLevels:2,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:3,SPG:(QuadPrefixTree(maxLevels:7,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:3,SPG:(QuadPrefixTree(maxLevels:7,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:4,SPG:(QuadPrefixTree(maxLevels:8,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-3,SPG:(QuadPrefixTree(maxLevels:1,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:3,SPG:(QuadPrefixTree(maxLevels:7,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:3,SPG:(QuadPrefixTree(maxLevels:7,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:0,SPG:(QuadPrefixTree(maxLevels:4,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:1,SPG:(QuadPrefixTree(maxLevels:5,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-3,SPG:(QuadPrefixTree(maxLevels:1,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:0,SPG:(QuadPrefixTree(maxLevels:4,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:1,SPG:(QuadPrefixTree(maxLevels:5,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:0,SPG:(QuadPrefixTree(maxLevels:4,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:1,SPG:(QuadPrefixTree(maxLevels:5,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:1,SPG:(QuadPrefixTree(maxLevels:5,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:0,SPG:(QuadPrefixTree(maxLevels:4,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:0,SPG:(QuadPrefixTree(maxLevels:4,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-1,SPG:(QuadPrefixTree(maxLevels:3,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:3,SPG:(QuadPrefixTree(maxLevels:7,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-1,SPG:(QuadPrefixTree(maxLevels:3,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:0,SPG:(QuadPrefixTree(maxLevels:4,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:0,SPG:(QuadPrefixTree(maxLevels:4,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-2,SPG:(QuadPrefixTree(maxLevels:2,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-2,SPG:(QuadPrefixTree(maxLevels:2,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:3,SPG:(QuadPrefixTree(maxLevels:7,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-3,SPG:(QuadPrefixTree(maxLevels:1,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-2,SPG:(QuadPrefixTree(maxLevels:2,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:3,SPG:(QuadPrefixTree(maxLevels:7,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:1,SPG:(QuadPrefixTree(maxLevels:5,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:0,SPG:(QuadPrefixTree(maxLevels:4,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-3,SPG:(QuadPrefixTree(maxLevels:1,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-1,SPG:(QuadPrefixTree(maxLevels:3,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-3,SPG:(QuadPrefixTree(maxLevels:1,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 2> Ig:ShapePair(Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=0.0) , Rect(minX=0.0,maxX=256.0,minY=0.0,maxY=128.0)) Qg:Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=SpatialOpRecursivePrefixTreeTest -Dtests.method="testContains {#5 seed=[AEDB749B8C7ED7ED:1AAA2819BFF6214C]}" -Dtests.seed=AEDB749B8C7ED7ED -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=zh_CN -Dtests.timezone=Africa/Asmera -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 0.11s J0 | SpatialOpRecursivePrefixTreeTest.testContains {#5 seed=[AEDB749B8C7ED7ED:1AAA2819BFF6214C]} <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: Shouldn't match I #0:ShapePair(Rect(minX=121.0,maxX=137.0,minY=-117.0,maxY=-109.0) , Rect(minX=124.0,maxX=129.0,minY=22.0,maxY=27.0)) Q:Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([AEDB749B8C7ED7ED:1AAA2819BFF6214C]:0)
[junit4:junit4] > at org.apache.lucene.spatial.prefix.SpatialOpRecursivePrefixTreeTest.fail(SpatialOpRecursivePrefixTreeTest.java:287)
[junit4:junit4] > at org.apache.lucene.spatial.prefix.SpatialOpRecursivePrefixTreeTest.doTest(SpatialOpRecursivePrefixTreeTest.java:273)
[junit4:junit4] > at org.apache.lucene.spatial.prefix.SpatialOpRecursivePrefixTreeTest.testContains(SpatialOpRecursivePrefixTreeTest.java:101)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:4,SPG:(QuadPrefixTree(maxLevels:8,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:2,SPG:(QuadPrefixTree(maxLevels:6,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:-2,SPG:(QuadPrefixTree(maxLevels:2,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 1> Strategy: RecursivePrefixTreeStrategy(prefixGridScanLevel:3,SPG:(QuadPrefixTree(maxLevels:7,ctx:SpatialContext{geo=false, calculator=CartesianDistCalc, worldBounds=Rect(minX=0.0,maxX=256.0,minY=-128.0,maxY=128.0)})))
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=Memory doPackFST= false), SpatialOpRecursivePrefixTreeTest=PostingsFormat(name=Memory doPackFST= false)}, docValues:{}, sim=DefaultSimilarity, locale=zh_CN, timezone=Africa/Asmera
[junit4:junit4] 2> NOTE: Linux 3.2.0-45-generic i386/Oracle Corporation 1.7.0_21 (32-bit)/cpus=8,threads=1,free=4243064,total=16252928
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SpatialOpRecursivePrefixTreeTest]
[junit4:junit4] Completed on J0 in 2.67s, 42 tests, 1 failure <<< FAILURES!
[...truncated 38 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: 12 suites, 69 tests, 1 failure, 2 ignored (2 assumptions)
Total time: 18 minutes 25 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -client -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure