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/15 20:01:15 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.7.0_21) - Build #
6151 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6151/
Java: 32bit/jdk1.7.0_21 -client -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch
Error Message:
shard3 is not consistent. Got 42 from http://127.0.0.1:54315/collection1lastClient and got 40 from http://127.0.0.1:44368/collection1
Stack Trace:
java.lang.AssertionError: shard3 is not consistent. Got 42 from http://127.0.0.1:54315/collection1lastClient and got 40 from http://127.0.0.1:44368/collection1
at __randomizedtesting.SeedInfo.seed([DF9620A717568AA:8C1FEC12062A0896]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9527 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4] 2> 385289 T1390 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 385295 T1390 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeySafeLeaderTest-1371318272608
[junit4:junit4] 2> 385296 T1390 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 385296 T1391 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 385396 T1390 oasc.ZkTestServer.run start zk server on port:42819
[junit4:junit4] 2> 385398 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 385495 T1397 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b21322 name:ZooKeeperConnection Watcher:127.0.0.1:42819 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 385495 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 385496 T1390 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 385500 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 385501 T1399 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a5d115 name:ZooKeeperConnection Watcher:127.0.0.1:42819/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 385501 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 385502 T1390 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 385504 T1390 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 385506 T1390 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 385508 T1390 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 385510 T1390 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 385511 T1390 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 385514 T1390 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 385515 T1390 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 385517 T1390 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 385518 T1390 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 385520 T1390 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 385521 T1390 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 385523 T1390 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 385524 T1390 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 385526 T1390 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 385527 T1390 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 385529 T1390 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 385530 T1390 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 385532 T1390 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 385533 T1390 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 385535 T1390 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 385536 T1390 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 385612 T1390 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 385625 T1390 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55904
[junit4:junit4] 2> 385626 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 385627 T1390 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 385627 T1390 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371318272852
[junit4:junit4] 2> 385628 T1390 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371318272852/solr.xml
[junit4:junit4] 2> 385628 T1390 oasc.CoreContainer.<init> New CoreContainer 8881935
[junit4:junit4] 2> 385629 T1390 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371318272852/'
[junit4:junit4] 2> 385629 T1390 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371318272852/'
[junit4:junit4] 2> 385712 T1390 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 385712 T1390 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 385713 T1390 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 385713 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 385714 T1390 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 385714 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 385714 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 385715 T1390 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 385715 T1390 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 385715 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 385719 T1390 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 385719 T1390 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42819/solr
[junit4:junit4] 2> 385720 T1390 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 385721 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 385722 T1410 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@185924f name:ZooKeeperConnection Watcher:127.0.0.1:42819 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 385723 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 385724 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 385727 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 385729 T1412 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4b8510 name:ZooKeeperConnection Watcher:127.0.0.1:42819/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 385729 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 385730 T1390 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 385733 T1390 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 385735 T1390 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 385736 T1390 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55904_
[junit4:junit4] 2> 385737 T1390 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55904_
[junit4:junit4] 2> 385740 T1390 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 385746 T1390 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 385748 T1390 oasc.Overseer.start Overseer (id=89870714314031107-127.0.0.1:55904_-n_0000000000) starting
[junit4:junit4] 2> 385750 T1390 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 385753 T1414 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 385753 T1390 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 385756 T1390 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 385757 T1390 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 385759 T1413 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 385762 T1415 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 385762 T1415 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 387262 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 387263 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[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:55904_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55904"}
[junit4:junit4] 2> 387263 T1413 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 387264 T1413 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 387267 T1412 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> 387763 T1415 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371318272852/collection1
[junit4:junit4] 2> 387764 T1415 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 387765 T1415 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 387765 T1415 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 387766 T1415 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371318272852/collection1/'
[junit4:junit4] 2> 387767 T1415 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371318272852/collection1/lib/README' to classloader
[junit4:junit4] 2> 387768 T1415 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371318272852/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 387800 T1415 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 387841 T1415 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 387843 T1415 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 387847 T1415 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 388277 T1415 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 388283 T1415 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 388286 T1415 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 388296 T1415 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 388299 T1415 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 388302 T1415 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 388303 T1415 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 388303 T1415 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 388303 T1415 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 388304 T1415 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 388304 T1415 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 388304 T1415 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 388311 T1415 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1371318272852/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/control/data/
[junit4:junit4] 2> 388311 T1415 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@417ee9
[junit4:junit4] 2> 388311 T1415 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 388312 T1415 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/control/data
[junit4:junit4] 2> 388312 T1415 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/control/data/index/
[junit4:junit4] 2> 388312 T1415 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 388313 T1415 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/control/data/index
[junit4:junit4] 2> 388317 T1415 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 388317 T1415 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 388318 T1415 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 388319 T1415 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 388319 T1415 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 388320 T1415 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 388320 T1415 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 388320 T1415 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 388320 T1415 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 388321 T1415 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 388321 T1415 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 388323 T1415 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 388326 T1415 oass.SolrIndexSearcher.<init> Opening Searcher@10b407d main
[junit4:junit4] 2> 388327 T1415 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 388327 T1415 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 388331 T1416 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10b407d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 388331 T1415 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 388331 T1415 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55904 collection:control_collection shard:shard1
[junit4:junit4] 2> 388332 T1415 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 388337 T1415 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 388339 T1415 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 388339 T1415 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 388339 T1415 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55904/collection1/
[junit4:junit4] 2> 388339 T1415 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 388340 T1415 oasc.SyncStrategy.syncToMe http://127.0.0.1:55904/collection1/ has no replicas
[junit4:junit4] 2> 388340 T1415 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:55904/collection1/
[junit4:junit4] 2> 388340 T1415 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 388770 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 388777 T1412 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> 388795 T1415 oasc.ZkController.register We are http://127.0.0.1:55904/collection1/ and leader is http://127.0.0.1:55904/collection1/
[junit4:junit4] 2> 388796 T1415 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55904
[junit4:junit4] 2> 388796 T1415 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 388796 T1415 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 388796 T1415 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 388798 T1415 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 388799 T1390 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 388800 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 388800 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 388803 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 388804 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 388806 T1419 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@bcf000 name:ZooKeeperConnection Watcher:127.0.0.1:42819/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 388806 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 388807 T1390 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 388809 T1390 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 388871 T1390 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 388872 T1390 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:41717
[junit4:junit4] 2> 388873 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 388874 T1390 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 388874 T1390 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371318276122
[junit4:junit4] 2> 388875 T1390 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371318276122/solr.xml
[junit4:junit4] 2> 388875 T1390 oasc.CoreContainer.<init> New CoreContainer 29705778
[junit4:junit4] 2> 388876 T1390 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371318276122/'
[junit4:junit4] 2> 388876 T1390 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371318276122/'
[junit4:junit4] 2> 388934 T1390 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 388934 T1390 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 388935 T1390 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 388935 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 388935 T1390 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 388936 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 388936 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 388936 T1390 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 388937 T1390 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 388937 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 388940 T1390 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 388941 T1390 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42819/solr
[junit4:junit4] 2> 388941 T1390 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 388942 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 388943 T1430 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1fb0bce name:ZooKeeperConnection Watcher:127.0.0.1:42819 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 388944 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 388945 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 388949 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 388950 T1432 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12c8fd3 name:ZooKeeperConnection Watcher:127.0.0.1:42819/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 388950 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 388953 T1390 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 389955 T1390 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41717_
[junit4:junit4] 2> 389957 T1390 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41717_
[junit4:junit4] 2> 389959 T1412 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 389959 T1412 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> 389960 T1419 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 389960 T1432 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 389964 T1433 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 389965 T1433 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 390281 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 390282 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[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:55904_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55904"}
[junit4:junit4] 2> 390284 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"3",
[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:41717_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41717"}
[junit4:junit4] 2> 390285 T1413 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4] 2> 390285 T1413 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 390289 T1432 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> 390289 T1419 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> 390289 T1412 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> 390966 T1433 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371318276122/collection1
[junit4:junit4] 2> 390966 T1433 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 390967 T1433 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 390967 T1433 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 390968 T1433 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371318276122/collection1/'
[junit4:junit4] 2> 390969 T1433 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371318276122/collection1/lib/README' to classloader
[junit4:junit4] 2> 390969 T1433 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371318276122/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 391005 T1433 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 391040 T1433 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 391042 T1433 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 391046 T1433 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 391479 T1433 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 391485 T1433 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 391488 T1433 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 391500 T1433 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 391503 T1433 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 391506 T1433 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 391507 T1433 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 391507 T1433 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 391507 T1433 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 391508 T1433 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 391509 T1433 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 391509 T1433 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 391509 T1433 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1371318276122/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty1/
[junit4:junit4] 2> 391509 T1433 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@417ee9
[junit4:junit4] 2> 391510 T1433 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 391510 T1433 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty1
[junit4:junit4] 2> 391510 T1433 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty1/index/
[junit4:junit4] 2> 391511 T1433 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 391511 T1433 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty1/index
[junit4:junit4] 2> 391513 T1433 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 391514 T1433 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 391515 T1433 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 391515 T1433 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 391516 T1433 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 391517 T1433 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 391517 T1433 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 391517 T1433 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 391518 T1433 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 391518 T1433 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 391518 T1433 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 391521 T1433 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 391524 T1433 oass.SolrIndexSearcher.<init> Opening Searcher@b7d754 main
[junit4:junit4] 2> 391524 T1433 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 391524 T1433 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 391529 T1434 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b7d754 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 391530 T1433 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 391530 T1433 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:41717 collection:collection1 shard:shard1
[junit4:junit4] 2> 391531 T1433 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 391536 T1433 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 391538 T1433 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 391539 T1433 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 391539 T1433 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:41717/collection1/
[junit4:junit4] 2> 391539 T1433 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 391539 T1433 oasc.SyncStrategy.syncToMe http://127.0.0.1:41717/collection1/ has no replicas
[junit4:junit4] 2> 391539 T1433 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:41717/collection1/
[junit4:junit4] 2> 391540 T1433 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 391793 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 391799 T1419 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> 391799 T1412 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> 391799 T1432 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> 391847 T1433 oasc.ZkController.register We are http://127.0.0.1:41717/collection1/ and leader is http://127.0.0.1:41717/collection1/
[junit4:junit4] 2> 391848 T1433 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:41717
[junit4:junit4] 2> 391848 T1433 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 391848 T1433 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 391849 T1433 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 391850 T1433 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 391851 T1390 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 391851 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 391852 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 391917 T1390 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 391919 T1390 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:45426
[junit4:junit4] 2> 391920 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 391920 T1390 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 391921 T1390 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371318279168
[junit4:junit4] 2> 391921 T1390 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371318279168/solr.xml
[junit4:junit4] 2> 391921 T1390 oasc.CoreContainer.<init> New CoreContainer 31186718
[junit4:junit4] 2> 391922 T1390 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371318279168/'
[junit4:junit4] 2> 391922 T1390 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371318279168/'
[junit4:junit4] 2> 391978 T1390 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 391978 T1390 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 391979 T1390 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 391979 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 391979 T1390 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 391980 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 391980 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 391980 T1390 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 391981 T1390 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 391981 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 391984 T1390 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 391985 T1390 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42819/solr
[junit4:junit4] 2> 391985 T1390 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 391986 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 391987 T1446 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@cac599 name:ZooKeeperConnection Watcher:127.0.0.1:42819 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 391987 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 391989 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 391992 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 391993 T1448 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1694ad name:ZooKeeperConnection Watcher:127.0.0.1:42819/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 391993 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 391996 T1390 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 392998 T1390 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45426_
[junit4:junit4] 2> 392999 T1390 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:45426_
[junit4:junit4] 2> 393004 T1432 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> 393004 T1412 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 393004 T1419 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 393005 T1412 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> 393005 T1448 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 393005 T1419 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> 393006 T1432 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 393011 T1449 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 393011 T1449 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 393304 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 393305 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"3",
[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:41717_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41717"}
[junit4:junit4] 2> 393308 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"3",
[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:45426_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45426"}
[junit4:junit4] 2> 393308 T1413 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 393308 T1413 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 393311 T1432 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> 393311 T1448 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> 393311 T1419 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> 393311 T1412 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> 394013 T1449 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371318279168/collection1
[junit4:junit4] 2> 394013 T1449 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 394014 T1449 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 394014 T1449 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 394015 T1449 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371318279168/collection1/'
[junit4:junit4] 2> 394016 T1449 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371318279168/collection1/lib/README' to classloader
[junit4:junit4] 2> 394016 T1449 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371318279168/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 394053 T1449 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 394091 T1449 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 394092 T1449 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 394096 T1449 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 394514 T1449 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 394520 T1449 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 394523 T1449 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 394532 T1449 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 394535 T1449 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 394538 T1449 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 394539 T1449 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 394539 T1449 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 394540 T1449 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 394541 T1449 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 394541 T1449 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 394541 T1449 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 394541 T1449 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1371318279168/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty2/
[junit4:junit4] 2> 394541 T1449 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@417ee9
[junit4:junit4] 2> 394542 T1449 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 394542 T1449 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty2
[junit4:junit4] 2> 394542 T1449 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty2/index/
[junit4:junit4] 2> 394543 T1449 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 394543 T1449 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty2/index
[junit4:junit4] 2> 394545 T1449 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 394546 T1449 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 394547 T1449 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 394548 T1449 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 394548 T1449 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 394549 T1449 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 394549 T1449 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 394549 T1449 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 394550 T1449 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 394550 T1449 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 394551 T1449 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 394553 T1449 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 394556 T1449 oass.SolrIndexSearcher.<init> Opening Searcher@ecfb02 main
[junit4:junit4] 2> 394556 T1449 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 394557 T1449 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 394562 T1450 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ecfb02 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 394564 T1449 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 394564 T1449 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:45426 collection:collection1 shard:shard2
[junit4:junit4] 2> 394565 T1449 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 394570 T1449 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 394571 T1449 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 394572 T1449 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 394572 T1449 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:45426/collection1/
[junit4:junit4] 2> 394572 T1449 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 394572 T1449 oasc.SyncStrategy.syncToMe http://127.0.0.1:45426/collection1/ has no replicas
[junit4:junit4] 2> 394572 T1449 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:45426/collection1/
[junit4:junit4] 2> 394573 T1449 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 394818 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 394824 T1412 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> 394824 T1419 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> 394824 T1432 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> 394824 T1448 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> 394827 T1449 oasc.ZkController.register We are http://127.0.0.1:45426/collection1/ and leader is http://127.0.0.1:45426/collection1/
[junit4:junit4] 2> 394829 T1449 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45426
[junit4:junit4] 2> 394829 T1449 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 394829 T1449 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 394829 T1449 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 394831 T1449 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 394832 T1390 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 394832 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 394833 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 394915 T1390 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 394917 T1390 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50844
[junit4:junit4] 2> 394917 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 394918 T1390 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 394918 T1390 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371318282150
[junit4:junit4] 2> 394918 T1390 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371318282150/solr.xml
[junit4:junit4] 2> 394919 T1390 oasc.CoreContainer.<init> New CoreContainer 17562905
[junit4:junit4] 2> 394919 T1390 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371318282150/'
[junit4:junit4] 2> 394920 T1390 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371318282150/'
[junit4:junit4] 2> 394967 T1390 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 394968 T1390 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 394968 T1390 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 394968 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 394969 T1390 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 394969 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 394969 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 394970 T1390 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 394970 T1390 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 394970 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 394973 T1390 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 394974 T1390 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42819/solr
[junit4:junit4] 2> 394974 T1390 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 394975 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 394976 T1462 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16fe345 name:ZooKeeperConnection Watcher:127.0.0.1:42819 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 394976 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 394978 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 394981 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 394982 T1464 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@137537c name:ZooKeeperConnection Watcher:127.0.0.1:42819/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 394982 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 394986 T1390 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 395988 T1390 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50844_
[junit4:junit4] 2> 395989 T1390 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50844_
[junit4:junit4] 2> 395991 T1432 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> 395991 T1448 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> 395995 T1412 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 395995 T1464 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 395995 T1419 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 395995 T1412 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> 395995 T1419 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> 395996 T1432 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 395997 T1448 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 396002 T1465 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 396002 T1465 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 396330 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 396331 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"3",
[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:45426_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45426"}
[junit4:junit4] 2> 396333 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"3",
[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:50844_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50844"}
[junit4:junit4] 2> 396334 T1413 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 396334 T1413 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 396337 T1419 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> 396337 T1448 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> 396338 T1412 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> 396337 T1432 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> 396337 T1464 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> 397003 T1465 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371318282150/collection1
[junit4:junit4] 2> 397004 T1465 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 397005 T1465 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 397005 T1465 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 397006 T1465 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371318282150/collection1/'
[junit4:junit4] 2> 397006 T1465 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371318282150/collection1/lib/README' to classloader
[junit4:junit4] 2> 397007 T1465 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371318282150/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 397043 T1465 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 397079 T1465 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 397080 T1465 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 397084 T1465 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 397504 T1465 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 397510 T1465 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 397513 T1465 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 397522 T1465 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 397525 T1465 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 397528 T1465 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 397529 T1465 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 397529 T1465 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 397530 T1465 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 397530 T1465 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 397530 T1465 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 397531 T1465 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 397531 T1465 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1371318282150/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty3/
[junit4:junit4] 2> 397531 T1465 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@417ee9
[junit4:junit4] 2> 397532 T1465 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 397532 T1465 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty3
[junit4:junit4] 2> 397532 T1465 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty3/index/
[junit4:junit4] 2> 397533 T1465 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 397533 T1465 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty3/index
[junit4:junit4] 2> 397535 T1465 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 397536 T1465 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 397537 T1465 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 397537 T1465 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 397538 T1465 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 397538 T1465 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 397539 T1465 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 397539 T1465 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 397539 T1465 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 397540 T1465 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 397540 T1465 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 397543 T1465 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 397546 T1465 oass.SolrIndexSearcher.<init> Opening Searcher@e1337 main
[junit4:junit4] 2> 397546 T1465 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 397547 T1465 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 397551 T1466 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e1337 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 397553 T1465 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 397553 T1465 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50844 collection:collection1 shard:shard3
[junit4:junit4] 2> 397570 T1465 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4] 2> 397578 T1465 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 397579 T1465 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 397580 T1465 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 397580 T1465 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50844/collection1/
[junit4:junit4] 2> 397580 T1465 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 397580 T1465 oasc.SyncStrategy.syncToMe http://127.0.0.1:50844/collection1/ has no replicas
[junit4:junit4] 2> 397580 T1465 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50844/collection1/
[junit4:junit4] 2> 397581 T1465 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4] 2> 397843 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 397849 T1419 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> 397849 T1412 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> 397849 T1464 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> 397849 T1448 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> 397849 T1432 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> 397887 T1465 oasc.ZkController.register We are http://127.0.0.1:50844/collection1/ and leader is http://127.0.0.1:50844/collection1/
[junit4:junit4] 2> 397888 T1465 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50844
[junit4:junit4] 2> 397888 T1465 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 397888 T1465 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 397888 T1465 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 397890 T1465 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 397891 T1390 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 397891 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 397892 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 397958 T1390 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 397960 T1390 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57390
[junit4:junit4] 2> 397960 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 397961 T1390 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 397961 T1390 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371318285208
[junit4:junit4] 2> 397962 T1390 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371318285208/solr.xml
[junit4:junit4] 2> 397962 T1390 oasc.CoreContainer.<init> New CoreContainer 4022776
[junit4:junit4] 2> 397962 T1390 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371318285208/'
[junit4:junit4] 2> 397963 T1390 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371318285208/'
[junit4:junit4] 2> 398010 T1390 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 398011 T1390 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 398011 T1390 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 398012 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 398012 T1390 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 398012 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 398013 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 398013 T1390 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 398013 T1390 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 398014 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 398017 T1390 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 398017 T1390 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42819/solr
[junit4:junit4] 2> 398018 T1390 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 398018 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 398020 T1478 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11c0958 name:ZooKeeperConnection Watcher:127.0.0.1:42819 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 398020 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 398021 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 398024 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 398026 T1480 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13230dc name:ZooKeeperConnection Watcher:127.0.0.1:42819/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 398026 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 398029 T1390 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 399031 T1390 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57390_
[junit4:junit4] 2> 399032 T1390 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57390_
[junit4:junit4] 2> 399035 T1432 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> 399035 T1448 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> 399036 T1412 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 399036 T1480 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 399036 T1464 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 399036 T1419 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 399037 T1464 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> 399036 T1412 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> 399051 T1448 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 399050 T1432 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 399037 T1419 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> 399055 T1481 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 399056 T1481 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 399353 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 399354 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard3",
[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:50844_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50844"}
[junit4:junit4] 2> 399357 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[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:57390_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57390"}
[junit4:junit4] 2> 399357 T1413 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 399357 T1413 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 399360 T1432 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> 399360 T1480 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> 399360 T1448 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> 399360 T1412 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> 399360 T1419 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> 399360 T1464 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> 400057 T1481 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371318285208/collection1
[junit4:junit4] 2> 400057 T1481 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 400058 T1481 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 400058 T1481 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 400059 T1481 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371318285208/collection1/'
[junit4:junit4] 2> 400060 T1481 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371318285208/collection1/lib/README' to classloader
[junit4:junit4] 2> 400060 T1481 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371318285208/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 400088 T1481 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 400135 T1481 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 400137 T1481 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 400141 T1481 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 400557 T1481 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 400563 T1481 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 400566 T1481 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 400575 T1481 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 400578 T1481 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 400581 T1481 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 400582 T1481 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 400583 T1481 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 400583 T1481 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 400593 T1481 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 400593 T1481 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 400594 T1481 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 400594 T1481 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1371318285208/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/
[junit4:junit4] 2> 400594 T1481 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@417ee9
[junit4:junit4] 2> 400595 T1481 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 400596 T1481 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4
[junit4:junit4] 2> 400596 T1481 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index/
[junit4:junit4] 2> 400596 T1481 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 400597 T1481 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index
[junit4:junit4] 2> 400599 T1481 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 400600 T1481 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 400601 T1481 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 400601 T1481 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 400602 T1481 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 400602 T1481 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 400603 T1481 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 400603 T1481 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 400603 T1481 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 400604 T1481 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 400604 T1481 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 400607 T1481 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 400610 T1481 oass.SolrIndexSearcher.<init> Opening Searcher@cfcb5f main
[junit4:junit4] 2> 400610 T1481 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 400610 T1481 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 400616 T1482 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@cfcb5f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 400619 T1481 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 400619 T1481 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57390 collection:collection1 shard:shard1
[junit4:junit4] 2> 400622 T1481 oasc.ZkController.register We are http://127.0.0.1:57390/collection1/ and leader is http://127.0.0.1:41717/collection1/
[junit4:junit4] 2> 400622 T1481 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57390
[junit4:junit4] 2> 400622 T1481 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 400623 T1481 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C24993 name=collection1 org.apache.solr.core.SolrCore@1ce4b3 url=http://127.0.0.1:57390/collection1 node=127.0.0.1:57390_ C24993_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:57390_, base_url=http://127.0.0.1:57390}
[junit4:junit4] 2> 400623 T1483 C24993 P57390 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 400624 T1481 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 400624 T1483 C24993 P57390 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 400624 T1483 C24993 P57390 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 400624 T1483 C24993 P57390 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 400625 T1390 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 400625 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 400626 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 400629 T1483 C24993 P57390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 400632 T1428 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 400693 T1390 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 400695 T1390 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57711
[junit4:junit4] 2> 400695 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 400696 T1390 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 400696 T1390 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371318287942
[junit4:junit4] 2> 400697 T1390 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371318287942/solr.xml
[junit4:junit4] 2> 400697 T1390 oasc.CoreContainer.<init> New CoreContainer 31438602
[junit4:junit4] 2> 400697 T1390 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371318287942/'
[junit4:junit4] 2> 400698 T1390 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371318287942/'
[junit4:junit4] 2> 400755 T1390 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 400756 T1390 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 400756 T1390 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 400756 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 400757 T1390 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 400757 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 400757 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 400758 T1390 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 400758 T1390 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 400758 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 400761 T1390 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 400762 T1390 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42819/solr
[junit4:junit4] 2> 400762 T1390 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 400763 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 400764 T1495 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14308a6 name:ZooKeeperConnection Watcher:127.0.0.1:42819 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 400765 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 400767 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 400770 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 400771 T1497 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@789022 name:ZooKeeperConnection Watcher:127.0.0.1:42819/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 400771 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 400775 T1390 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 400865 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 400866 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[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:57390_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57390"}
[junit4:junit4] 2> 400870 T1419 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> 400870 T1412 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> 400870 T1464 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> 400870 T1480 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> 400870 T1448 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> 400870 T1432 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> 400871 T1497 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> 401632 T1428 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 401633 T1428 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:57390_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 401777 T1390 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57711_
[junit4:junit4] 2> 401778 T1390 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57711_
[junit4:junit4] 2> 401780 T1497 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> 401780 T1419 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 401780 T1448 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> 401780 T1464 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 401780 T1432 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> 401781 T1464 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 401781 T1412 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 401781 T1419 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 401781 T1480 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 401782 T1412 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 401783 T1448 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 401783 T1480 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 401784 T1497 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 401783 T1432 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 401786 T1498 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 401787 T1498 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 402374 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 402375 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[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:57711_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57711"}
[junit4:junit4] 2> 402375 T1413 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 402376 T1413 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 402379 T1419 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 402379 T1497 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 402380 T1448 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 402380 T1412 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 402379 T1432 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 402379 T1480 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 402379 T1464 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 402788 T1498 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371318287942/collection1
[junit4:junit4] 2> 402788 T1498 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 402789 T1498 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 402789 T1498 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 402790 T1498 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371318287942/collection1/'
[junit4:junit4] 2> 402791 T1498 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371318287942/collection1/lib/README' to classloader
[junit4:junit4] 2> 402791 T1498 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371318287942/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 402819 T1498 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 402862 T1498 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 402863 T1498 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 402867 T1498 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 403286 T1498 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 403309 T1498 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 403311 T1498 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 403321 T1498 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 403324 T1498 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 403327 T1498 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 403328 T1498 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 403329 T1498 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 403329 T1498 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 403330 T1498 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 403330 T1498 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 403330 T1498 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 403330 T1498 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1371318287942/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/
[junit4:junit4] 2> 403331 T1498 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@417ee9
[junit4:junit4] 2> 403331 T1498 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 403331 T1498 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5
[junit4:junit4] 2> 403332 T1498 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index/
[junit4:junit4] 2> 403332 T1498 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 403332 T1498 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index
[junit4:junit4] 2> 403335 T1498 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 403335 T1498 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 403337 T1498 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 403337 T1498 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 403337 T1498 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 403338 T1498 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 403339 T1498 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 403339 T1498 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 403339 T1498 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 403340 T1498 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 403340 T1498 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 403342 T1498 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 403345 T1498 oass.SolrIndexSearcher.<init> Opening Searcher@8e329e main
[junit4:junit4] 2> 403346 T1498 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 403346 T1498 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 403351 T1499 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8e329e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 403352 T1498 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 403352 T1498 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57711 collection:collection1 shard:shard2
[junit4:junit4] 2> 403355 T1498 oasc.ZkController.register We are http://127.0.0.1:57711/collection1/ and leader is http://127.0.0.1:45426/collection1/
[junit4:junit4] 2> 403355 T1498 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57711
[junit4:junit4] 2> 403355 T1498 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 403356 T1498 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C24994 name=collection1 org.apache.solr.core.SolrCore@4ce7 url=http://127.0.0.1:57711/collection1 node=127.0.0.1:57711_ C24994_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:57711_, base_url=http://127.0.0.1:57711}
[junit4:junit4] 2> 403356 T1500 C24994 P57711 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 403356 T1498 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 403357 T1500 C24994 P57711 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 403357 T1500 C24994 P57711 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 403357 T1500 C24994 P57711 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 403357 T1390 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 403358 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 403358 T1500 C24994 P57711 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 403358 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 403362 T1442 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 403423 T1390 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 403424 T1390 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:33254
[junit4:junit4] 2> 403426 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 403426 T1390 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 403426 T1390 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371318290674
[junit4:junit4] 2> 403427 T1390 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371318290674/solr.xml
[junit4:junit4] 2> 403427 T1390 oasc.CoreContainer.<init> New CoreContainer 20738696
[junit4:junit4] 2> 403427 T1390 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371318290674/'
[junit4:junit4] 2> 403428 T1390 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371318290674/'
[junit4:junit4] 2> 403485 T1390 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 403485 T1390 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 403486 T1390 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 403486 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 403487 T1390 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 403487 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 403487 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 403488 T1390 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 403489 T1390 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 403490 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 403493 T1390 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 403494 T1390 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42819/solr
[junit4:junit4] 2> 403494 T1390 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 403495 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 403496 T1512 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a025ca name:ZooKeeperConnection Watcher:127.0.0.1:42819 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 403497 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 403498 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 403501 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 403502 T1514 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5db7f9 name:ZooKeeperConnection Watcher:127.0.0.1:42819/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 403503 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 403506 T1390 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C24995 name=collection1 org.apache.solr.core.SolrCore@1ce4b3 url=http://127.0.0.1:57390/collection1 node=127.0.0.1:57390_ C24995_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57390_, base_url=http://127.0.0.1:57390}
[junit4:junit4] 2> 403633 T1483 C24995 P57390 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:41717/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 403634 T1483 C24995 P57390 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:57390 START replicas=[http://127.0.0.1:41717/collection1/] nUpdates=100
[junit4:junit4] 2> 403634 T1483 C24995 P57390 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 403635 T1483 C24995 P57390 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 403635 T1483 C24995 P57390 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 403635 T1483 C24995 P57390 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 403635 T1483 C24995 P57390 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 403635 T1483 C24995 P57390 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:41717/collection1/. core=collection1
[junit4:junit4] 2> 403636 T1483 C24995 P57390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C24996 name=collection1 org.apache.solr.core.SolrCore@16aa6e8 url=http://127.0.0.1:41717/collection1 node=127.0.0.1:41717_ C24996_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:41717_, base_url=http://127.0.0.1:41717, leader=true}
[junit4:junit4] 2> 403640 T1428 C24996 P41717 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 403643 T1425 C24996 P41717 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 403644 T1425 C24996 P41717 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 403645 T1425 C24996 P41717 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 403654 T1425 C24996 P41717 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 403654 T1425 C24996 P41717 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 403655 T1425 C24996 P41717 oass.SolrIndexSearcher.<init> Opening Searcher@fc63fb realtime
[junit4:junit4] 2> 403655 T1425 C24996 P41717 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 403655 T1425 C24996 P41717 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 13
[junit4:junit4] 2> 403656 T1483 C24995 P57390 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 403657 T1483 C24995 P57390 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 403658 T1427 C24996 P41717 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 403659 T1427 C24996 P41717 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 403659 T1483 C24995 P57390 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 403660 T1483 C24995 P57390 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 403660 T1483 C24995 P57390 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 403662 T1428 C24996 P41717 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 403662 T1483 C24995 P57390 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 403663 T1483 C24995 P57390 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index.20130615224450975
[junit4:junit4] 2> 403663 T1483 C24995 P57390 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index.20130615224450975 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4a674 fullCopy=false
[junit4:junit4] 2> 403666 T1425 C24996 P41717 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> 403667 T1483 C24995 P57390 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 403674 T1483 C24995 P57390 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 403674 T1483 C24995 P57390 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 403676 T1483 C24995 P57390 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 403676 T1483 C24995 P57390 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 403677 T1483 C24995 P57390 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 403677 T1483 C24995 P57390 oass.SolrIndexSearcher.<init> Opening Searcher@71a84f main
[junit4:junit4] 2> 403678 T1482 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@71a84f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 403678 T1483 C24995 P57390 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index.20130615224450975 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index.20130615224450975;done=true>>]
[junit4:junit4] 2> 403679 T1483 C24995 P57390 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index.20130615224450975
[junit4:junit4] 2> 403679 T1483 C24995 P57390 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty4/index.20130615224450975
[junit4:junit4] 2> 403679 T1483 C24995 P57390 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 403679 T1483 C24995 P57390 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 403680 T1483 C24995 P57390 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 403680 T1483 C24995 P57390 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 403682 T1483 C24995 P57390 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 403884 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 403885 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[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:57711_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57711"}
[junit4:junit4] 2> 403888 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[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:57390_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57390"}
[junit4:junit4] 2> 403907 T1419 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 403907 T1432 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 403908 T1480 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 403908 T1514 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 403907 T1497 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 403907 T1412 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 403907 T1448 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 403907 T1464 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 404363 T1442 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 404363 T1442 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=6&state=recovering&nodeName=127.0.0.1:57711_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 404508 T1390 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33254_
[junit4:junit4] 2> 404509 T1390 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:33254_
[junit4:junit4] 2> 404511 T1432 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 404511 T1497 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 404511 T1514 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 404512 T1419 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 404512 T1419 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 404512 T1464 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 404512 T1464 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 404511 T1448 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 404513 T1412 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 404513 T1412 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 404514 T1497 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 404514 T1514 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 404512 T1480 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 404515 T1448 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 404513 T1432 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 404515 T1480 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 404519 T1517 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 404520 T1517 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 405414 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 405415 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"7",
[junit4:junit4] 2> "numShards":"3",
[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:33254_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33254"}
[junit4:junit4] 2> 405415 T1413 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 405415 T1413 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 405418 T1412 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 405419 T1464 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 405419 T1497 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 405419 T1514 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 405419 T1432 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 405419 T1448 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 405418 T1419 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 405418 T1480 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 405521 T1517 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371318290674/collection1
[junit4:junit4] 2> 405521 T1517 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 405522 T1517 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 405522 T1517 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 405523 T1517 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371318290674/collection1/'
[junit4:junit4] 2> 405523 T1517 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371318290674/collection1/lib/README' to classloader
[junit4:junit4] 2> 405524 T1517 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371318290674/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 405563 T1517 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 405598 T1517 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 405599 T1517 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 405603 T1517 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 406021 T1517 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 406027 T1517 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 406030 T1517 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 406040 T1517 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 406043 T1517 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 406046 T1517 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 406047 T1517 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 406047 T1517 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 406047 T1517 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 406048 T1517 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 406048 T1517 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 406049 T1517 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 406049 T1517 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1371318290674/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/
[junit4:junit4] 2> 406049 T1517 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@417ee9
[junit4:junit4] 2> 406050 T1517 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 406050 T1517 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6
[junit4:junit4] 2> 406050 T1517 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index/
[junit4:junit4] 2> 406051 T1517 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 406051 T1517 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index
[junit4:junit4] 2> 406054 T1517 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 406054 T1517 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 406055 T1517 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 406056 T1517 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 406056 T1517 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 406057 T1517 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 406057 T1517 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 406057 T1517 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 406058 T1517 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 406058 T1517 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 406059 T1517 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 406061 T1517 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 406064 T1517 oass.SolrIndexSearcher.<init> Opening Searcher@68f2da main
[junit4:junit4] 2> 406064 T1517 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 406064 T1517 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 406069 T1518 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@68f2da main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 406071 T1517 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 406071 T1517 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:33254 collection:collection1 shard:shard3
[junit4:junit4] 2> 406074 T1517 oasc.ZkController.register We are http://127.0.0.1:33254/collection1/ and leader is http://127.0.0.1:50844/collection1/
[junit4:junit4] 2> 406074 T1517 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:33254
[junit4:junit4] 2> 406075 T1517 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 406075 T1517 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C24997 name=collection1 org.apache.solr.core.SolrCore@1c68306 url=http://127.0.0.1:33254/collection1 node=127.0.0.1:33254_ C24997_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:33254_, base_url=http://127.0.0.1:33254}
[junit4:junit4] 2> 406075 T1519 C24997 P33254 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 406075 T1517 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 406076 T1519 C24997 P33254 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 406076 T1519 C24997 P33254 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 406077 T1519 C24997 P33254 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 406077 T1390 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 406077 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 406077 T1519 C24997 P33254 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 406078 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 406083 T1458 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 406142 T1390 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 406152 T1390 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:41237
[junit4:junit4] 2> 406153 T1390 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 406154 T1390 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 406154 T1390 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371318293395
[junit4:junit4] 2> 406155 T1390 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371318293395/solr.xml
[junit4:junit4] 2> 406155 T1390 oasc.CoreContainer.<init> New CoreContainer 21031401
[junit4:junit4] 2> 406156 T1390 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371318293395/'
[junit4:junit4] 2> 406156 T1390 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1371318293395/'
[junit4:junit4] 2> 406223 T1390 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 406224 T1390 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 406224 T1390 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 406224 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 406225 T1390 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 406225 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 406225 T1390 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 406226 T1390 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 406226 T1390 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 406226 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 406230 T1390 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 406230 T1390 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42819/solr
[junit4:junit4] 2> 406230 T1390 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 406231 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 406232 T1531 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b8026f name:ZooKeeperConnection Watcher:127.0.0.1:42819 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 406233 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 406235 T1390 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 406238 T1390 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 406239 T1533 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9127e8 name:ZooKeeperConnection Watcher:127.0.0.1:42819/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 406240 T1390 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 406242 T1390 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C24998 name=collection1 org.apache.solr.core.SolrCore@4ce7 url=http://127.0.0.1:57711/collection1 node=127.0.0.1:57711_ C24998_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57711_, base_url=http://127.0.0.1:57711}
[junit4:junit4] 2> 406364 T1500 C24998 P57711 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:45426/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 406364 T1500 C24998 P57711 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:57711 START replicas=[http://127.0.0.1:45426/collection1/] nUpdates=100
[junit4:junit4] 2> 406365 T1500 C24998 P57711 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 406365 T1500 C24998 P57711 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 406365 T1500 C24998 P57711 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 406366 T1500 C24998 P57711 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 406366 T1500 C24998 P57711 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 406366 T1500 C24998 P57711 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:45426/collection1/. core=collection1
[junit4:junit4] 2> 406366 T1500 C24998 P57711 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C24999 name=collection1 org.apache.solr.core.SolrCore@9d0fe8 url=http://127.0.0.1:45426/collection1 node=127.0.0.1:45426_ C24999_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:45426_, base_url=http://127.0.0.1:45426, leader=true}
[junit4:junit4] 2> 406372 T1444 C24999 P45426 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> 406376 T1441 C24999 P45426 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 406379 T1441 C24999 P45426 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 406379 T1441 C24999 P45426 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 406394 T1441 C24999 P45426 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 406394 T1441 C24999 P45426 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 406395 T1441 C24999 P45426 oass.SolrIndexSearcher.<init> Opening Searcher@129cab6 realtime
[junit4:junit4] 2> 406396 T1441 C24999 P45426 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 406396 T1441 C24999 P45426 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 20
[junit4:junit4] 2> 406397 T1500 C24998 P57711 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 406397 T1500 C24998 P57711 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 406399 T1442 C24999 P45426 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 406399 T1442 C24999 P45426 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 406400 T1500 C24998 P57711 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 406400 T1500 C24998 P57711 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 406400 T1500 C24998 P57711 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 406402 T1444 C24999 P45426 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> 406403 T1500 C24998 P57711 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 406403 T1500 C24998 P57711 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index.20130615224453716
[junit4:junit4] 2> 406404 T1500 C24998 P57711 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index.20130615224453716 lockFactory=org.apache.lucene.store.NativeFSLockFactory@124fc37 fullCopy=false
[junit4:junit4] 2> 406406 T1441 C24999 P45426 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> ASYNC NEW_CORE C25000 name=collection1 org.apache.solr.core.SolrCore@4ce7 url=http://127.0.0.1:57711/collection1 node=127.0.0.1:57711_ C25000_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57711_, base_url=http://127.0.0.1:57711}
[junit4:junit4] 2> 406416 T1500 C25000 P57711 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 406424 T1500 C25000 P57711 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 406424 T1500 C25000 P57711 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 406426 T1500 C25000 P57711 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 406427 T1500 C25000 P57711 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 406427 T1500 C25000 P57711 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 406427 T1500 C25000 P57711 oass.SolrIndexSearcher.<init> Opening Searcher@68479e main
[junit4:junit4] 2> 406429 T1499 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@68479e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 406429 T1500 C25000 P57711 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index.20130615224453716 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index.20130615224453716;done=true>>]
[junit4:junit4] 2> 406430 T1500 C25000 P57711 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index.20130615224453716
[junit4:junit4] 2> 406430 T1500 C25000 P57711 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty5/index.20130615224453716
[junit4:junit4] 2> 406430 T1500 C25000 P57711 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 406431 T1500 C25000 P57711 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 406431 T1500 C25000 P57711 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 406431 T1500 C25000 P57711 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 406432 T1500 C25000 P57711 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 406923 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 406924 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"7",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard3",
[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:33254_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33254"}
[junit4:junit4] 2> 406927 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[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:57711_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57711"}
[junit4:junit4] 2> 406930 T1419 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 406930 T1497 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 406931 T1533 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 406931 T1448 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 406931 T1412 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 406930 T1480 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 406930 T1464 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 406930 T1514 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 406930 T1432 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 407083 T1458 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 407084 T1458 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=7&state=recovering&nodeName=127.0.0.1:33254_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 407244 T1390 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41237_
[junit4:junit4] 2> 407245 T1390 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41237_
[junit4:junit4] 2> 407247 T1514 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 407247 T1432 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 407247 T1448 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 407248 T1464 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 407248 T1497 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 407248 T1419 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 407249 T1514 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 407248 T1464 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 407248 T1480 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 407249 T1412 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 407249 T1419 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 407250 T1412 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 407250 T1432 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 407250 T1533 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 407250 T1480 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 407251 T1497 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 407250 T1448 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 407252 T1533 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 407257 T1536 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 407257 T1536 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 408437 T1413 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 408438 T1413 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"8",
[junit4:junit4] 2> "numShards":"3",
[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:41237_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41237"}
[junit4:junit4] 2> 408438 T1413 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 408438 T1413 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 408442 T1419 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 408443 T1448 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 408443 T1480 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 408443 T1533 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 408443 T1464 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 408443 T1497 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 408443 T1412 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 408443 T1514 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 408442 T1432 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> ASYNC NEW_CORE C25001 name=collection1 org.apache.solr.core.SolrCore@1c68306 url=http://127.0.0.1:33254/collection1 node=127.0.0.1:33254_ C25001_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:33254_, base_url=http://127.0.0.1:33254}
[junit4:junit4] 2> 409085 T1519 C25001 P33254 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50844/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 409086 T1519 C25001 P33254 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:33254 START replicas=[http://127.0.0.1:50844/collection1/] nUpdates=100
[junit4:junit4] 2> 409086 T1519 C25001 P33254 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 409087 T1519 C25001 P33254 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 409087 T1519 C25001 P33254 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 409087 T1519 C25001 P33254 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 409088 T1519 C25001 P33254 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 409088 T1519 C25001 P33254 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50844/collection1/. core=collection1
[junit4:junit4] 2> 409088 T1519 C25001 P33254 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C25002 name=collection1 org.apache.solr.core.SolrCore@1ce46c0 url=http://127.0.0.1:50844/collection1 node=127.0.0.1:50844_ C25002_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50844_, base_url=http://127.0.0.1:50844, leader=true}
[junit4:junit4] 2> 409092 T1457 C25002 P50844 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 409093 T1459 C25002 P50844 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 409095 T1459 C25002 P50844 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 409096 T1459 C25002 P50844 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 409104 T1459 C25002 P50844 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty3/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 409104 T1459 C25002 P50844 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 409105 T1459 C25002 P50844 oass.SolrIndexSearcher.<init> Opening Searcher@36b284 realtime
[junit4:junit4] 2> 409105 T1459 C25002 P50844 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 409105 T1459 C25002 P50844 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 12
[junit4:junit4] 2> 409106 T1519 C25001 P33254 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 409106 T1519 C25001 P33254 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 409107 T1458 C25002 P50844 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 409108 T1458 C25002 P50844 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 409108 T1519 C25001 P33254 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 409109 T1519 C25001 P33254 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 409109 T1519 C25001 P33254 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 409111 T1457 C25002 P50844 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 409111 T1519 C25001 P33254 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 409112 T1519 C25001 P33254 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index.20130615224456425
[junit4:junit4] 2> 409112 T1519 C25001 P33254 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index.20130615224456425 lockFactory=org.apache.lucene.store.NativeFSLockFactory@12db2ce fullCopy=false
[junit4:junit4] 2> 409115 T1459 C25002 P50844 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> 409116 T1519 C25001 P33254 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 409124 T1519 C25001 P33254 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 409125 T1519 C25001 P33254 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 409126 T1519 C25001 P33254 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 409127 T1519 C25001 P33254 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 409127 T1519 C25001 P33254 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 409128 T1519 C25001 P33254 oass.SolrIndexSearcher.<init> Opening Searcher@4adb48 main
[junit4:junit4] 2> 409129 T1518 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4adb48 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 409130 T1519 C25001 P33254 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index.20130615224456425 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index.20130615224456425;done=true>>]
[junit4:junit4] 2> 409130 T1519 C25001 P33254 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index.20130615224456425
[junit4:junit4] 2> 409130 T1519 C25001 P33254 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty6/index.20130615224456425
[junit4:junit4] 2> 409131 T1519 C25001 P33254 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 409131 T1519 C25001 P33254 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 409131 T1519 C25001 P33254 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 409131 T1519 C25001 P33254 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 409133 T1519 C25001 P33254 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=c
[...truncated too long message...]
,null}
[junit4:junit4] 2> 520519 T1630 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> 520519 T1840 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 520521 T1630 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4:junit4] 2> 520521 T1839 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 520523 T1839 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 520523 T1839 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"12",
[junit4:junit4] 2> "numShards":null,
[junit4:junit4] 2> "shard":"shard2",
[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:53072_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53072"}
[junit4:junit4] 2> 520526 T1630 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> 520566 T1390 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 44368
[junit4:junit4] 2> 520567 T1390 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=20616469
[junit4:junit4] 2> 521568 T1390 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 521569 T1390 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 521570 T1390 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@25720e
[junit4:junit4] 2> 521571 T1390 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=22,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=76,cumulative_deletesById=36,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 521572 T1390 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 521572 T1390 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 521572 T1390 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 521574 T1390 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 521574 T1390 oasc.CachingDirectoryFactory.close Closing StandardDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 521574 T1390 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty12 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty12;done=false>>]
[junit4:junit4] 2> 521575 T1390 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty12
[junit4:junit4] 2> 521575 T1390 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty12/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty12/index;done=false>>]
[junit4:junit4] 2> 521575 T1390 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371318272608/jetty12/index
[junit4:junit4] 2> 521576 T1839 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89870714314031132-127.0.0.1:44368_-n_0000000012) am no longer a leader.
[junit4:junit4] 2> 521579 T1630 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> 521579 T1630 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 521580 T1630 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 521601 T1390 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 521677 T1390 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 521678 T1390 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:42819 42819
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeySafeLeaderTest -Dtests.method=testDistribSearch -Dtests.seed=DF9620A717568AA -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_TN -Dtests.timezone=Asia/Dushanbe -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 136s J1 | ChaosMonkeySafeLeaderTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard3 is not consistent. Got 42 from http://127.0.0.1:54315/collection1lastClient and got 40 from http://127.0.0.1:44368/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([DF9620A717568AA:8C1FEC12062A0896]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 521698 T1390 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 136412 T1389 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> 521792 T1609 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 521793 T1609 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> 521793 T1609 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene40, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=ar_TN, timezone=Asia/Dushanbe
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.7.0_21 (32-bit)/cpus=8,threads=1,free=54110600,total=173584384
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SolrIndexConfigTest, RequestHandlersTest, FullSolrCloudDistribCmdsTest, SampleTest, CurrencyFieldOpenExchangeTest, TestCopyFieldCollectionResource, ShardRoutingCustomTest, OpenCloseCoreStressTest, StatsComponentTest, TestElisionMultitermQuery, URLClassifyProcessorTest, PathHierarchyTokenizerFactoryTest, TestRangeQuery, TestPropInject, TestCollationField, SolrCmdDistributorTest, DOMUtilTest, TestAtomicUpdateErrorCases, JSONWriterTest, TimeZoneUtilsTest, UniqFieldsUpdateProcessorFactoryTest, TestSolrQueryParserResource, MultiTermTest, CurrencyFieldXmlFileTest, XsltUpdateRequestHandlerTest, TestDistributedGrouping, NumericFieldsTest, TestSolr4Spatial, LeaderElectionIntegrationTest, TestAnalyzedSuggestions, CopyFieldTest, OpenExchangeRatesOrgProviderTest, TestAddFieldRealTimeGet, TestBinaryResponseWriter, TestCoreDiscovery, TestMultiCoreConfBootstrap, BasicDistributedZk2Test, TestStressLucene, TestWordDelimiterFilterFactory, IndexReaderFactoryTest, FieldAnalysisRequestHandlerTest, TestDefaultSearchFieldResource, SpellPossibilityIteratorTest, DistanceFunctionTest, HighlighterTest, ChaosMonkeySafeLeaderTest]
[junit4:junit4] Completed on J1 in 136.70s, 1 test, 1 failure <<< FAILURES!
[...truncated 565 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:366: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:887: There were test failures: 296 suites, 1243 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 44 minutes 51 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -client -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure